Strange output in planSummary in slow queries in logs?

[Seth Mason]

Hi all --

I'm trying to track down a slow query that's causing queued reads to spike.

While I was looking at the logs, I noticed some entries had the same index

repeated whereas others did not in the planSummary.

For example:

2014-11-29T06:53:38.857+0000 [conn757586] query foobar.baz query: { $query: { $and: [ { created: { $lte: 1417243972000 } }, { deleted: 0 }, { owner: "d09b16c953aa40c98dd8c513526aca5a" }, { toggle_id: "baz_foo_02" } ] }, $orderby: { created: -1 } } planSummary: IXSCAN { toggle_id: 1 }, IXSCAN { toggle_id: 1 } ntoskip:0 nscanned:1723 nscannedObjects:1723 keyUpdates:0 numYields:13 locks(micros) r:312624 nreturned:1 reslen:3995 605ms

2014-11-29T06:53:39.121+0000 [conn759585] query foobar.baz query: { $query: { $and: [ { created: { $lte: 1417243948000 } }, { deleted: 0 }, { owner: "b00a38e0feb64052ba92d57907c9363a" }, { toggle_id: "TOGGLE3_Toggler_P" } ] }, $orderby: { created: -1 } } planSummary: IXSCAN { created: -1 } ntoskip:0 nscanned:153869 nscannedObjects:153869 keyUpdates:0 numYields:1191 locks(micros) r:12247574 nreturned:1 reslen:3349 26101ms

In the first line above, it has planSummary: IXSCAN { toggle_id: 1 }, IXSCAN {

toggle_id: 1 } but in the second line it has 'planSummary: IXSCAN { created:

-1 }'.

I have indexes on 'toggler_id' and 'created':

{

"v" : 1,

"key" : {

"toggler_id" : 1

},

"name" : "toggler_id_1",

"ns" : "foobar.baz",

"background" : true

},

{

"v" : 1,

"key" : {

"created" : -1

},

"name" : "created_-1",

"ns" : "foobar.baz",

"background" : true

},

{

"v" : 1,

"key" : {

"created" : 1

},

"name" : "created_1",

"ns" : "foobar.baz",

"background" : true

}

My first question is why does the 'toggler_id' show up twice whereas 'created' a

single time in the planSummary? I have yet to see a line where 'toggler_id'

doesn't show up twice or 'created' once.

And my next is why does mongo sometimes choose 'toggler_id' but other times

choose created for the index to use? Is it just beause it arbitrarily picks

one because they both seem to be the optimal index?

Thanks in advance for help,

[Asya Kamsky]

Seth:

The ones that have a sort (orderby) will list two indexes, one for filter, one for sorting - it's kind of an artifact of how the query optimizer planned the query, but that's why you won't see that on all queries.

As far as why it picks one or the other, read about how it works here:

http://docs.mongodb.org/manual/core/query-plans/

Asya

P.S. usually read queue will spike because of inefficient write as reads can share the read lock, but sometimes a poorly indexed read can make all operations slow.

--
You received this message because you are subscribed to the Google Groups "mongodb-user"
group.
 
For other MongoDB technical support options, see: http://www.mongodb.org/about/support/.
---
You received this message because you are subscribed to the Google Groups "mongodb-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mongodb-user...@googlegroups.com.
To post to this group, send email to mongod...@googlegroups.com.
Visit this group at http://groups.google.com/group/mongodb-user.
To view this discussion on the web visit https://groups.google.com/d/msgid/mongodb-user/6eb3f641-67b5-4463-83da-bd667f920326%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.