CODEWITHSUNDEEP
mongodbdatabase-performance
Manish Trivedi
Manish Trivedi

Reputation: 3559

Explain MongoDB log output

I have location-collection with indexing timestamp_1, timestamp_2 and user_id field. When executing query (you can see in following log) then query taking ~3 min (175670ms). I don't recognize why is It happening!! I have attached following MongoDB-Log.
Can anybody explain me following log and how can I optimise it ??

2017-04-12T17:04:33.759+0000 I COMMAND [conn167] query location-collection query: { orderby: { timestamp_1: 1 }, $query: { $and: [ { timestamp_1: { $lte: 1492016294486.0 } }, { timestamp_2: { $gte: 1491993563400.0 } }, { user_id: "jkfjlsjfflki-14asddsd" } ] } } planSummary: IXSCAN { user_id: 1 }, IXSCAN { user_id: 1 } ntoreturn:1000 ntoskip:0 keysExamined:27254 docsExamined:27254 hasSortStage:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:3350 nreturned:67 reslen:176574 locks:{ Global: { acquireCount: { r: 6702 } }, Database: { acquireCount: { r: 3351 } }, Collection: { acquireCount: { r: 3351 } } } 175670ms

One more question: I am creating my own value of "_id" field so any drawback this way ?? I am creating just string value and expecting mongoDb index it without any issues.

2017-04-12T17:04:41.979+0000 I COMMAND [conn150] query db.users query: { orderby: { _id: 1 }, $query: { _id: "USR-dfhsddf-14905426shfkjdhf" } } planSummary: IDHACK ntoreturn:1 ntoskip:0 keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:1291 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 2627ms

Thanks in Advance!!

Upvotes: 1

Views: 7100

Answers (1)

Jeff J
Jeff J

Reputation: 573

Answering the second question first - It is fine to use your own value for _id. MongoDB will index it properly. The consequence of doing this is that it is now your applications responsibility to ensure that there are no duplicates.

The default MonogDB ObjectId type also includes the timestamp in the value. This means that ordering by the _id field when it is an ObjectId will return results by insertion order (or technically timestamp when the ObjectId was created order).

As for the log output, query performance output values are from the Database Profiler. You can see the list of values at https://docs.mongodb.com/manual/reference/database-profiler/.

A very useful tool for the query performance is explain(), https://docs.mongodb.com/manual/reference/method/cursor.explain/ and https://docs.mongodb.com/manual/reference/explain-results/. You will have to test on your own systems how the queries perform.

It seems as though you have three different indexes on your collection on the individual fields: timestamp_1, timestamp_2, and user_id.

The query is comparing three fields:

  • timestamp_1 is less than a value
  • timestamp_2 is greater than a value
  • user_id equals a value

You are also ordering by the timestamp_1 field in the output.

The planSummary: IXSCAN { user_id: 1 }, IXSCAN { user_id: 1 } is stating that the query planner is choosing the index on user_id for the query, then choosing the index on user_id again to use for sorting, which is not the the field you actually want to sort on. For reference, see https://groups.google.com/forum/#!topic/mongodb-user/nQlmVdODo-M.

The keysExamined:27254 means that the index scan examined 27254 keys in the index. The docsExamined:27254 means that MongoDB pulled up 27245 documents off of disk to examine the contents. The nreturned:67 states that the result of the query returned 67 documents. The user_id index is scanned, finds 27254 matches, then each document is retrieved from the collection. Those documents are parsed and timestamp* fields are compared, and the 67 matching records are returned. The timestamp_1 and timestamp_2 indexes are not used.

MongoDB stores indexes as B-TREEs and does allow compound indexes (https://docs.mongodb.com/manual/indexes/). You can test making new combinations of indexes, profile the results, and see which one works best for your application. A compound index with all three fields will allow the query to analyze all of the query fields (user_id, timestamp_1, and timestamp_2) using only the index, which should reduce the number of documents that MongoDB needs to read off of disk. One potential example is:

db.collection.createIndex({user_id:1, timestamp_1:1, timestamp_2:-1)

This index would allow the Mongo query planner to match the user_id field, then find results where timestamp_1 is less than the value, then find any more results where timestamp_2 is greater than its value. Because timestamp_1 is listed before timestamp_2, the matching records are already sorted, which may also allow MongoDB to skip the sort phase. You will need to test this on your own system to verify that its performance is better. Depending on the cardinality of the documents in the collection, you could try putting the timestamp fields ahead of the user_id field.

Upvotes: 9

Related Questions