Strange output in planSummary in slow queries in logs?

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?

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/

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.