I have a mongo query which costs different time from java code and shell. Java code is below,
The version of mongo server is v2.6.5 , and version v2.4.8 doesn't have the question.
DBObject obj = new BasicDBObject();
obj.put("accountId",accountId);
List<DBObject> listOr = new ArrayList<DBObject>();
listOr.add(new BasicDBObject("status", 11));
listOr.add(new BasicDBObject("status", 12));
obj.put("$or", listOr);
BasicDBObject andDB = new BasicDBObject();
andDB.append("$gt", 0);
andDB.append("$lt",4514185);
obj.put("currBoardId",andDB);
DBCursor cur = null;
cur = coll.find(obj,new BasicDBObject("currBoardId",1)).sort(new BasicDBObject("commentId",-1)).limit(10);
when I run the code, I can get slow query record from profile collection. It shows "nscanned" : 1566031 and "millis" : 4724 .
> db.system.profile.find().sort({$natural:-1}).limit(10);
{ "op" : "query", "ns" : "l_comment.comment", "query" : { "$query" : { "accountId" : NumberLong(4), "$or" : [ { "status" : 11 }, { "status" : 12 } ], "currBoardId" : { "$gt" : 0, "$lt" : NumberLong(4514185) } }, "$orderby" : { "commentId" : -1 } }, "cursorid" : 220355902849, "ntoreturn" : 10, "ntoskip" : 0, "nscanned" : 1566031, "nscannedObjects" : 1566031, "keyUpdates" : 0, "numYield" : 5, "lockStats" : { "timeLockedMicros" : { "r" : NumberLong(8921271), "w" : NumberLong(0) }, "timeAcquiringMicros" : { "r" : NumberLong(14), "w" : NumberLong(2) } }, "nreturned" : 10, "responseLength" : 410, "millis" : 4724, "execStats" : { "type" : "PROJECTION", "works" : 1566031, "yields" : 12234, "unyields" : 12234, "invalidates" : 0, "advanced" : 10, "needTime" : 0, "needFetch" : 0, "isEOF" : 0, "children" : [ { "type" : "FETCH", "works" : 1566031, "yields" : 12234, "unyields" : 12234, "invalidates" : 0, "advanced" : 10, "needTime" : 1566021, "needFetch" : 0, "isEOF" : 0, "alreadyHasObj" : 0, "forcedFetches" : 0, "matchTested" : 10, "children" : [ { "type" : "IXSCAN", "works" : 1566031, "yields" : 12234, "unyields" : 12234, "invalidates" : 0, "advanced" : 1566031, "needTime" : 0, "needFetch" : 0, "isEOF" : 0, "keyPattern" : "{ commentId: -1.0 }", "isMultiKey" : 0, "boundsVerbose" : "field #0['commentId']: [MaxKey, MinKey]", "yieldMovedCursor" : 0, "dupsTested" : 0, "dupsDropped" : 0, "seenInvalidated" : 0, "matchTested" : 0, "keysExamined" : 1566031, "children" : [ ] } ] } ] }, "ts" : ISODate("2015-02-10T08:51:16.195Z"), "client" : "192.168.66.103", "allUsers" : [ ], "user" : "" }
But when I run the query from shell, it returns fast.
db.comment.find({ "accountId" : NumberLong(4), "$or" : [ { "status" : 11 }, { "status" : 12 } ], "currBoardId" : { "$gt" : 0, "$lt" : NumberLong(4514185) }}).sort({commentId:-1}).limit(10)
below is the output of it's explain. It shows the query scans 10517 records and use 109 millis. Why this happened, how can I improve the code?
Thanks for any tips and help.
{
"clauses" : [
{
"cursor" : "BtreeCursor idx_atst",
"isMultiKey" : false,
"n" : 10,
"nscannedObjects" : 10517,
"nscanned" : 10517,
"scanAndOrder" : true,
"indexOnly" : false,
"nChunkSkips" : 0,
"indexBounds" : {
"accountId" : [
[
NumberLong(4),
NumberLong(4)
]
],
"rootId" : [
[
{
"$maxElement" : 1
},
{
"$minElement" : 1
}
]
],
"status" : [
[
{
"$minElement" : 1
},
{
"$maxElement" : 1
}
]
],
"type" : [
[
{
"$minElement" : 1
},
{
"$maxElement" : 1
}
]
]
}
},
{
"cursor" : "BtreeCursor ",
"isMultiKey" : false,
"n" : 0,
"nscannedObjects" : 0,
"nscanned" : 0,
"scanAndOrder" : true,
"indexOnly" : false,
"nChunkSkips" : 0,
"indexBounds" : {
"accountId" : [
[
NumberLong(4),
NumberLong(4)
]
],
"rootId" : [
[
{
"$maxElement" : 1
},
{
"$minElement" : 1
}
]
],
"status" : [
[
{
"$minElement" : 1
},
{
"$maxElement" : 1
}
]
],
"type" : [
[
{
"$minElement" : 1
},
{
"$maxElement" : 1
}
]
]
}
}
],
"cursor" : "QueryOptimizerCursor",
"n" : 10,
"nscannedObjects" : 10517,
"nscanned" : 10517,
"nscannedObjectsAllPlans" : 31574,
"nscannedAllPlans" : 31574,
"scanAndOrder" : false,
"nYields" : 246,
"nChunkSkips" : 0,
"millis" : 109,
"server" : "app-sz-2-3.sz.chosk.net:27017",
"filterSet" : false,
"stats" : {
"type" : "KEEP_MUTATIONS",
"works" : 10529,
"yields" : 246,
"unyields" : 246,
"invalidates" : 0,
"advanced" : 10,
"needTime" : 10519,
"needFetch" : 0,
"isEOF" : 0,
"children" : [
{
"type" : "OR",
"works" : 10529,
"yields" : 246,
"unyields" : 246,
"invalidates" : 0,
"advanced" : 10,
"needTime" : 10519,
"needFetch" : 0,
"isEOF" : 0,
"dupsTested" : 10,
"dupsDropped" : 0,
"locsForgotten" : 0,
"matchTested_0" : 0,
"matchTested_1" : 0,
"children" : [
{
"type" : "SORT",
"works" : 10529,
"yields" : 246,
"unyields" : 246,
"invalidates" : 0,
"advanced" : 10,
"needTime" : 10518,
"needFetch" : 0,
"isEOF" : 1,
"forcedFetches" : 0,
"memUsage" : 4675,
"memLimit" : 33554432,
"children" : [
{
"type" : "FETCH",
"works" : 10518,
"yields" : 246,
"unyields" : 246,
"invalidates" : 0,
"advanced" : 1909,
"needTime" : 8608,
"needFetch" : 0,
"isEOF" : 1,
"alreadyHasObj" : 0,
"forcedFetches" : 0,
"matchTested" : 1909,
"children" : [
{
"type" : "IXSCAN",
"works" : 10518,
"yields" : 246,
"unyields" : 246,
"invalidates" : 0,
"advanced" : 10517,
"needTime" : 0,
"needFetch" : 0,
"isEOF" : 1,
"keyPattern" : "{ accountId: 1, rootId: -1.0, status: 1, type: 1 }",
"isMultiKey" : 0,
"boundsVerbose" : "field #0['accountId']: [4, 4], field #1['rootId']: [MaxKey, MinKey], field #2['status']: [MinKey, MaxKey], field #3['type']: [MinKey, MaxKey]",
"yieldMovedCursor" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0,
"matchTested" : 0,
"keysExamined" : 10517,
"children" : [ ]
}
]
}
]
},
{
"type" : "SORT",
"works" : 0,
"yields" : 246,
"unyields" : 246,
"invalidates" : 0,
"advanced" : 0,
"needTime" : 0,
"needFetch" : 0,
"isEOF" : 0,
"forcedFetches" : 0,
"memUsage" : 0,
"memLimit" : 33554432,
"children" : [
{
"type" : "FETCH",
"works" : 0,
"yields" : 246,
"unyields" : 246,
"invalidates" : 0,
"advanced" : 0,
"needTime" : 0,
"needFetch" : 0,
"isEOF" : 0,
"alreadyHasObj" : 0,
"forcedFetches" : 0,
"matchTested" : 0,
"children" : [
{
"type" : "IXSCAN",
"works" : 0,
"yields" : 246,
"unyields" : 246,
"invalidates" : 0,
"advanced" : 0,
"needTime" : 0,
"needFetch" : 0,
"isEOF" : 0,
"keyPattern" : "{}",
"isMultiKey" : 0,
"boundsVerbose" : "field #0['accountId']: [4, 4], field #1['rootId']: [MaxKey, MinKey], field #2['status']: [MinKey, MaxKey], field #3['type']: [MinKey, MaxKey]",
"yieldMovedCursor" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
"seenInvalidated" : 0,
"matchTested" : 0,
"keysExamined" : 0,
"children" : [ ]
}
]
}
]
}
]
}
]
}
}
new BasicDBObject("currBoardId",1)stripping the results should take some time but should not change the scanned Objects. Interesting. - SimulantaccountIdin java please. - Simulant{ "commentId" : -1 }while the query run from the shell used an index to handle the actual query predicate. This explains why thenscannedfor the Java query was much higher than for the shell query. Does this choice of index happen every time? Or is the Java query choosing the sort index only some of the time? Do you need the sort index for something else? Could you add the sort field to the shell query's index? - wdberkeley