|
Ok, happening again today on a different collection - db.teams. It started about 3 hours ago, which is when our user traffic starts to pick up for the day, but other than that nothing different happening to any other day or time.
Here's some of the requested output from a secondary where the query is happening:
The logs don't seem much different to logLevel 0 ( I executed db.runCommand(
{getParameter: 1, logLevel: 1}
) on the secondary ):
2015-04-27T16:08:35.237+0000 [conn92899] query ****.posts query: { $query: { _id: ObjectId('553db3601fcaa39585000dea') }, $orderby: { _id: 1 } } planSummary: IDHACK ntoskip:0 nscanned:1 nscannedObjects:1 idhack:1 keyUpdates:0 numYields:0 locks(micros) r:34 nreturned:1 reslen:407 0ms
|
2015-04-27T16:08:35.239+0000 [conn108638] command ****.$cmd command: count { count: "patients", query: { user_id: ObjectId('54fddc8b6bcd61b52a000716') } } planSummary: COUNT { user_id: 1 } keyUpdates:0 numYields:0 locks(micros) r:53 reslen:48 0ms
|
2015-04-27T16:08:35.240+0000 [conn108638] query ****.patients query: { $query: { user_id: ObjectId('54fddc8b6bcd61b52a000716') }, $orderby: { _id: 1 } } planSummary: IXSCAN { user_id: 1 }, IXSCAN { user_id: 1 } ntoskip:0 nscanned:1 nscannedObjects:1 keyUpdates:0 numYields:0 locks(micros) r:124 nreturned:1 reslen:526 0ms
|
2015-04-27T16:08:35.430+0000 [conn108638] query ****.teams query: { $query: { user_id: ObjectId('54fddc8b6bcd61b52a000716'), context: "epl" }, $orderby: { _id: 1 } } planSummary: IXSCAN { _id: 1 } ntoskip:0 nscanned:148667 nscannedObjects:148667 keyUpdates:0 numYields:0 locks(micros) r:183957 nreturned:1 reslen:564 183ms
|
2015-04-27T16:08:35.436+0000 [conn108638] command ****.$cmd command: count { count: "patients", query: { user_id: ObjectId('551d6bb56bcd617b52000b74') } } planSummary: COUNT { user_id: 1 } keyUpdates:0 numYields:0 locks(micros) r:90 reslen:48 0ms
|
2015-04-27T16:08:35.436+0000 [conn108638] query ****.patients query: { $query: { user_id: ObjectId('551d6bb56bcd617b52000b74') }, $orderby: { _id: 1 } } planSummary: IXSCAN { user_id: 1 }, IXSCAN { user_id: 1 } ntoskip:0 nscanned:1 nscannedObjects:1 keyUpdates:0 numYields:0 locks(micros) r:155 nreturned:1 reslen:547 0ms
|
rs:SECONDARY> db.teams.find({user_id: ObjectId('54fddc8b6bcd61b52a000716'), context: 'epl'}).sort({_id: 1}).explain(true)
|
{
|
"cursor" : "BtreeCursor user_id_1_context_1",
|
"isMultiKey" : false,
|
"n" : 1,
|
"nscannedObjects" : 1,
|
"nscanned" : 1,
|
"nscannedObjectsAllPlans" : 10,
|
"nscannedAllPlans" : 10,
|
"scanAndOrder" : true,
|
"indexOnly" : false,
|
"nYields" : 0,
|
"nChunkSkips" : 0,
|
"millis" : 0,
|
"indexBounds" : {
|
"user_id" : [
|
[
|
ObjectId("54fddc8b6bcd61b52a000716"),
|
ObjectId("54fddc8b6bcd61b52a000716")
|
]
|
],
|
"context" : [
|
[
|
"epl",
|
"epl"
|
]
|
]
|
},
|
"allPlans" : [
|
{
|
"cursor" : "BtreeCursor user_id_1_context_1",
|
"isMultiKey" : false,
|
"n" : 1,
|
"nscannedObjects" : 1,
|
"nscanned" : 1,
|
"scanAndOrder" : true,
|
"indexOnly" : false,
|
"nChunkSkips" : 0,
|
"indexBounds" : {
|
"user_id" : [
|
[
|
ObjectId("54fddc8b6bcd61b52a000716"),
|
ObjectId("54fddc8b6bcd61b52a000716")
|
]
|
],
|
"context" : [
|
[
|
"epl",
|
"epl"
|
]
|
]
|
}
|
},
|
{
|
"cursor" : "BtreeCursor _id_",
|
"isMultiKey" : false,
|
"n" : 0,
|
"nscannedObjects" : 5,
|
"nscanned" : 5,
|
"scanAndOrder" : false,
|
"indexOnly" : false,
|
"nChunkSkips" : 0,
|
"indexBounds" : {
|
"_id" : [
|
[
|
{
|
"$minElement" : 1
|
},
|
{
|
"$maxElement" : 1
|
}
|
]
|
]
|
}
|
},
|
{
|
"cursor" : "BtreeCursor context_1_provider_ids_1",
|
"isMultiKey" : true,
|
"n" : 0,
|
"nscannedObjects" : 4,
|
"nscanned" : 4,
|
"scanAndOrder" : true,
|
"indexOnly" : false,
|
"nChunkSkips" : 0,
|
"indexBounds" : {
|
"context" : [
|
[
|
"epl",
|
"epl"
|
]
|
],
|
"provider_ids" : [
|
[
|
{
|
"$minElement" : 1
|
},
|
{
|
"$maxElement" : 1
|
}
|
]
|
]
|
}
|
}
|
],
|
"server" : "****:27017",
|
"filterSet" : false,
|
"stats" : {
|
"type" : "SORT",
|
"works" : 6,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 1,
|
"needTime" : 2,
|
"needFetch" : 0,
|
"isEOF" : 1,
|
"forcedFetches" : 0,
|
"memUsage" : 552,
|
"memLimit" : 33554432,
|
"children" : [
|
{
|
"type" : "KEEP_MUTATIONS",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 1,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 1,
|
"children" : [
|
{
|
"type" : "FETCH",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 1,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 1,
|
"alreadyHasObj" : 0,
|
"forcedFetches" : 0,
|
"matchTested" : 0,
|
"children" : [
|
{
|
"type" : "IXSCAN",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 1,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 1,
|
"keyPattern" : "{ user_id: 1.0, context: 1.0 }",
|
"isMultiKey" : 0,
|
"boundsVerbose" : "field #0['user_id']: [ObjectId('54fddc8b6bcd61b52a000716'), ObjectId('54fddc8b6bcd61b52a000716')], field #1['context']: [\"epl\", \"epl\"]",
|
"yieldMovedCursor" : 0,
|
"dupsTested" : 0,
|
"dupsDropped" : 0,
|
"seenInvalidated" : 0,
|
"matchTested" : 0,
|
"keysExamined" : 1,
|
"children" : [ ]
|
}
|
]
|
}
|
]
|
}
|
]
|
}
|
}
|
rs:SECONDARY> db.teams.getPlanCache().getPlansByQuery({user_id: ObjectId('54fddc8b6bcd61b52a000716'), context: 'epl'}, {}, {_id: 1})
|
[
|
{
|
"details" : {
|
"solution" : "(whole index scan solution: dir=1; tree=Leaf { _id: 1 }, pos: 0\n)"
|
},
|
"reason" : {
|
"score" : 1.5003000000000002,
|
"stats" : {
|
"type" : "LIMIT",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 1,
|
"needTime" : 1,
|
"needFetch" : 0,
|
"isEOF" : 1,
|
"children" : [
|
{
|
"type" : "FETCH",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 1,
|
"needTime" : 1,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"alreadyHasObj" : 0,
|
"forcedFetches" : 0,
|
"matchTested" : 1,
|
"children" : [
|
{
|
"type" : "IXSCAN",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 2,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"keyPattern" : "{ _id: 1 }",
|
"isMultiKey" : 0,
|
"boundsVerbose" : "field #0['_id']: [MinKey, MaxKey]",
|
"yieldMovedCursor" : 0,
|
"dupsTested" : 0,
|
"dupsDropped" : 0,
|
"seenInvalidated" : 0,
|
"matchTested" : 0,
|
"keysExamined" : 2,
|
"children" : [ ]
|
}
|
]
|
}
|
]
|
}
|
},
|
"feedback" : {
|
"nfeedback" : 20,
|
"averageScore" : 1.0003116784495691,
|
"stdDevScore" : 0.000009274428678544542,
|
"scores" : [
|
{
|
"score" : 1.0003061120958376
|
},
|
{
|
"score" : 1.0003057959926507
|
},
|
{
|
"score" : 1.0003099475762731
|
},
|
{
|
"score" : 1.000311135857461
|
},
|
{
|
"score" : 1.0003058139872907
|
},
|
{
|
"score" : 1.0003078347187728
|
},
|
{
|
"score" : 1.0003078347187728
|
},
|
{
|
"score" : 1.0003061585076705
|
},
|
{
|
"score" : 1.0003100615768503
|
},
|
{
|
"score" : 1.000330536215952
|
},
|
{
|
"score" : 1.0003063062040436
|
},
|
{
|
"score" : 1.0003094269365285
|
},
|
{
|
"score" : 1.0003157649136083
|
},
|
{
|
"score" : 1.0003063062835809
|
},
|
{
|
"score" : 1.000309425070688
|
},
|
{
|
"score" : 1.0003104884469756
|
},
|
{
|
"score" : 1.0003063062040436
|
},
|
{
|
"score" : 1.000342890842805
|
},
|
{
|
"score" : 1.0003094269365285
|
},
|
{
|
"score" : 1.0003159959050483
|
}
|
]
|
},
|
"filterSet" : false
|
},
|
{
|
"details" : {
|
"solution" : "(index-tagged expression tree: tree=Node\n---Leaf { context: 1.0, provider_ids: 1.0 }, pos: 0\n---Leaf \n)"
|
},
|
"reason" : {
|
"score" : 1.0002,
|
"stats" : {
|
"type" : "KEEP_MUTATIONS",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 2,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"children" : [
|
{
|
"type" : "OR",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 2,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"dupsTested" : 0,
|
"dupsDropped" : 0,
|
"locsForgotten" : 0,
|
"matchTested_0" : 0,
|
"matchTested_1" : 0,
|
"children" : [
|
{
|
"type" : "SORT",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 1,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"forcedFetches" : 0,
|
"memUsage" : 0,
|
"memLimit" : 33554432,
|
"children" : [
|
{
|
"type" : "FETCH",
|
"works" : 1,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 1,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"alreadyHasObj" : 0,
|
"forcedFetches" : 0,
|
"matchTested" : 0,
|
"children" : [
|
{
|
"type" : "IXSCAN",
|
"works" : 1,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 1,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"keyPattern" : "{ context: 1.0, provider_ids: 1.0 }",
|
"isMultiKey" : 1,
|
"boundsVerbose" : "field #0['context']: [\"aut\", \"aut\"], field #1['provider_ids']: [MinKey, MaxKey]",
|
"yieldMovedCursor" : 0,
|
"dupsTested" : 1,
|
"dupsDropped" : 0,
|
"seenInvalidated" : 0,
|
"matchTested" : 0,
|
"keysExamined" : 1,
|
"children" : [ ]
|
}
|
]
|
}
|
]
|
},
|
{
|
"type" : "SORT",
|
"works" : 0,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"forcedFetches" : 0,
|
"memUsage" : 0,
|
"memLimit" : 33554432,
|
"children" : [
|
{
|
"type" : "FETCH",
|
"works" : 0,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"alreadyHasObj" : 0,
|
"forcedFetches" : 0,
|
"matchTested" : 0,
|
"children" : [
|
{
|
"type" : "IXSCAN",
|
"works" : 0,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"keyPattern" : "{ context: 1.0, provider_ids: 1.0 }",
|
"isMultiKey" : 1,
|
"boundsVerbose" : "field #0['context']: [\"aut\", \"aut\"], field #1['provider_ids']: [MinKey, MaxKey]",
|
"yieldMovedCursor" : 0,
|
"dupsTested" : 0,
|
"dupsDropped" : 0,
|
"seenInvalidated" : 0,
|
"matchTested" : 0,
|
"keysExamined" : 0,
|
"children" : [ ]
|
}
|
]
|
}
|
]
|
}
|
]
|
}
|
]
|
}
|
},
|
"feedback" : {
|
|
},
|
"filterSet" : false
|
},
|
{
|
"details" : {
|
"solution" : "(index-tagged expression tree: tree=Node\n---Leaf { user_id: 1.0, context: 1.0 }, pos: 1\n---Leaf { user_id: 1.0, context: 1.0 }, pos: 0\n)"
|
},
|
"reason" : {
|
"score" : 1.0002,
|
"stats" : {
|
"type" : "KEEP_MUTATIONS",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 2,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"children" : [
|
{
|
"type" : "OR",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 2,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"dupsTested" : 0,
|
"dupsDropped" : 0,
|
"locsForgotten" : 0,
|
"matchTested_0" : 0,
|
"matchTested_1" : 0,
|
"children" : [
|
{
|
"type" : "SORT",
|
"works" : 2,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 1,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"forcedFetches" : 0,
|
"memUsage" : 4007,
|
"memLimit" : 33554432,
|
"children" : [
|
{
|
"type" : "FETCH",
|
"works" : 1,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 1,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"alreadyHasObj" : 0,
|
"forcedFetches" : 0,
|
"matchTested" : 0,
|
"children" : [
|
{
|
"type" : "IXSCAN",
|
"works" : 1,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 1,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"keyPattern" : "{ user_id: 1.0, context: 1.0 }",
|
"isMultiKey" : 0,
|
"boundsVerbose" : "field #0['user_id']: [ObjectId('4f3457deff95ae61d700afd1'), ObjectId('4f3457deff95ae61d700afd1')], field #1['context']: [\"aut\", \"aut\"]",
|
"yieldMovedCursor" : 0,
|
"dupsTested" : 0,
|
"dupsDropped" : 0,
|
"seenInvalidated" : 0,
|
"matchTested" : 0,
|
"keysExamined" : 1,
|
"children" : [ ]
|
}
|
]
|
}
|
]
|
},
|
{
|
"type" : "SORT",
|
"works" : 0,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"forcedFetches" : 0,
|
"memUsage" : 0,
|
"memLimit" : 33554432,
|
"children" : [
|
{
|
"type" : "FETCH",
|
"works" : 0,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"alreadyHasObj" : 0,
|
"forcedFetches" : 0,
|
"matchTested" : 0,
|
"children" : [
|
{
|
"type" : "IXSCAN",
|
"works" : 0,
|
"yields" : 0,
|
"unyields" : 0,
|
"invalidates" : 0,
|
"advanced" : 0,
|
"needTime" : 0,
|
"needFetch" : 0,
|
"isEOF" : 0,
|
"keyPattern" : "{ user_id: 1.0, context: 1.0 }",
|
"isMultiKey" : 0,
|
"boundsVerbose" : "field #0['user_id']: [ObjectId('4f3457deff95ae61d700afd1'), ObjectId('4f3457deff95ae61d700afd1')], field #1['context']: [\"aut\", \"aut\"]",
|
"yieldMovedCursor" : 0,
|
"dupsTested" : 0,
|
"dupsDropped" : 0,
|
"seenInvalidated" : 0,
|
"matchTested" : 0,
|
"keysExamined" : 0,
|
"children" : [ ]
|
}
|
]
|
}
|
]
|
}
|
]
|
}
|
]
|
}
|
},
|
"feedback" : {
|
|
},
|
"filterSet" : false
|
}
|
]
|
Thanks for any advice!
Paul
|