3

This Query scans only one document and returns only one document. But this is very slow:

2017-05-22T07:13:24.548+0000 I COMMAND [conn40] query databasename.collectionname query: { _id: ObjectId('576d4ce3f2d62a001e84a9b8') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8009ms
2017-05-22T07:13:24.549+0000 I COMMAND [conn10] query databasename.collectionname query: { _id: ObjectId('576d4db35de5fa001ebdd77a') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8010ms
2017-05-22T07:13:24.553+0000 I COMMAND [conn47] query databasename.collectionname query: { _id: ObjectId('576d44b7ea8351001ea5fb22') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8014ms
2017-05-22T07:13:24.555+0000 I COMMAND [conn52] query databasename.collectionname query: { _id: ObjectId('576d457ceb82a0001e205bfa') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8015ms
2017-05-22T07:13:24.555+0000 I COMMAND [conn41] query databasename.collectionname query: { _id: ObjectId('576d457ec0697c001e1e1779') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8015ms
2017-05-22T07:13:24.555+0000 I COMMAND [conn39] query databasename.collectionname query: { _id: ObjectId('576d44b8ea8351001ea5fb27') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8015ms
2017-05-22T07:13:24.561+0000 I COMMAND [conn34] query databasename.collectionname query: { _id: ObjectId('576d44b55de5fa001ebdd31e') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8022ms
2017-05-22T07:13:24.564+0000 I COMMAND [conn32] query databasename.collectionname query: { _id: ObjectId('576d4df6d738a7001ef2a235') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8025ms
2017-05-22T07:13:24.564+0000 I COMMAND [conn51] query databasename.collectionname query: { _id: ObjectId('576d48165de5fa001ebdd55a') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8024ms
2017-05-22T07:13:24.564+0000 I COMMAND [conn17] query databasename.collectionname query: { _id: ObjectId('576d44c19f2382001e953717') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8025ms
2017-05-22T07:13:24.564+0000 I COMMAND [conn8] query databasename.collectionname query: { _id: ObjectId('576d45d256c22e001efdb382') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8025ms
2017-05-22T07:13:24.564+0000 I COMMAND [conn42] query databasename.collectionname query: { _id: ObjectId('576d44bd57c75e001e6e2302') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8025ms
2017-05-22T07:13:24.564+0000 I COMMAND [conn6] query databasename.collectionname query: { _id: ObjectId('576d44b394e731001e7cd530') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8025ms
2017-05-22T07:13:24.571+0000 I COMMAND [conn31] query databasename.collectionname query: { _id: ObjectId('576d4dbcb7289f001e64e32b') } planSummary: IDHACK ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 8032ms

This looks like very slow disk I/O. What does the planSummary: IDHACK mean? Any more info for IDHACK?

  • 2
    IDHACK is an optimal plan (fetching by _id) so the problem is definitely outside of plan selection. However, there currently isn't enough context to understand why these queries might be slow (eg. MongoDB version, detailed logs, I/O metrics, h/w details, ...). I/O bottlenecks are one possibility which you should be able to correlate with periods of slow queries and related MongoDB metrics for cache or memory. All of these queries happen within a very short sub-second interval so there are other possibilities including time adjustments (eg. +8s adjustment skewing the logged query times). – Stennie Jun 6 '17 at 13:50
10

It is just informing that mongod has chosen to use the _id index.

More specifically: IDHACK means that normal query plan path (evaluation, caching, re-evaluation) was bypassed for the query shape {_id: <value>} which is supported by the required _id index. This is a performance optimization for the common use case of fetching a document by primary key.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.