{var%20f='http://v.t.sina.com.cn/share/share.php?appkey=1515056452',u=z||d.location,p=['&url=',e(u),'&title=',e(t||d.title),'&source=',e(r),'&sourceUrl=',e(l),'&content=',c||'gb2312','&pic=',e(p||'')].join('');function%20a(){if(!window.open([f,p].join(''),'mb',['toolbar=0,status=0,resizable=1,width=440,height=430,left=',(s.width-440)/2,',top=',(s.height-430)/2].join('')))u.href=[f,p].join('');};if(/Firefox/.test(navigator.userAgent))setTimeout(a,0);else%20a();})(screen,document,encodeURIComponent,'','','https://www.manongdao.com/data/attach/logo/logo.png', '推荐 Juvenile、少年° 的问题《MongoDB Slow query by ID》','https://www.manongdao.com/q-396285.html','页面编码gb2312|utf-8默认gb2312'));){kind=link}
I recently migrated my MongoDB database from Windows Server to CentOS. The version is 2.4.9. I noticed that I have a slow retrieval of records by _id field! I ran a repair database over the weekend bu that did not solve the problem. I have this method that retrieves records by their IDs (with IN operator) (using spring data mongodb 1.4.1.RELEASE):
@Override
public Map<String, Record> findAsMapIds(
final String[] ids,
final ComponentType... comps
) {
if( null == ids || 0 == ids.length ) {
return null;
}
Map<String,Record> result = new HashMap<String,Record>();
final Criteria cr = where("_id").in( idArrFunction.apply(ids) );
final Query qry = new Query( cr );
setFieldsToReturn( qry, comps );
long start = System.currentTimeMillis();
List<Record> ritems = getTemplate().find(qry, Record.class);
long end = System.currentTimeMillis();
System.out.println( "findAsMapIds()::" + (end-start) );
for( Record r: ritems ) {
result.put( r.getId(), r );
}
return result;
}
public MongoOperations getTemplate() {
return template;
}
The function idArrFunction returns an array of ObjectId[]
You notice that I'm timing only the data retrieval call. Also I'm not passing more that 10 ids at a time. Here is the timing output that I'm getting in the logs when I call this method several times:
findAsMapIds()::2092
findAsMapIds()::6666
findAsMapIds()::10007
findAsMapIds()::15132
findAsMapIds()::18341
findAsMapIds()::24709
findAsMapIds()::28731
findAsMapIds()::33888
findAsMapIds()::36862
findAsMapIds()::40206
You notice that the time grows with each call I made to this method.
Here are the collection stats:
> db.record.stats();
{
"ns" : "mydb.record",
"count" : 1491427,
"size" : 18292198304,
"avgObjSize" : 12264.896843090544,
"storageSize" : 18899890096,
"numExtents" : 30,
"nindexes" : 13,
"lastExtentSize" : 2146426864,
"paddingFactor" : 1,
"systemFlags" : 1,
"userFlags" : 0,
"totalIndexSize" : 734401024,
"indexSizes" : {
"_id_" : 43561728,
"orgId" : 63192304,
"type" : 51018240,
"orgHierarchy" : 63274064,
"orgHierarchy_mrn" : 75603472,
"dos" : 25525472,
"org_pdt" : 77189616,
"orgHierarchy_processedDtTm" : 77287728,
"processedDtTm_-1" : 37536016,
"orgId_states" : 68367712,
"states" : 27553120,
"states_1_processedDtTm_-1" : 41624016,
"orgId_1_states_1_processedDtTm_-1" : 82667536
},
"ok" : 1
}
If I printout the Query object from java I get this:
Query: { "_id" : { "$in" : [ { "$oid" : "51cbe96dcb81c43374ca9516"} , { "$oid" : "51cbe892cb81c43374ca5e48"} , { "$oid" : "51cbe910cb81c43374ca7aba"} , { "$oid" : "51c00739cb81e6b83ad29d14"} , { "$oid" : "51c06ff4cb81e6b83ad4f69a"} , { "$oid" : "51c07010cb81e6b83ad4f74e"} , { "$oid" : "51c06da5cb81e6b83ad4e775"} , { "$oid" : "51c081bbcb81e6b83ad56437"} , { "$oid" : "51c07fe2cb81e6b83ad557d2"} , { "$oid" : "51c081bbcb81e6b83ad56433"}]}}, Fields: { "text" : 1 , "type" : 1 , "header" : 1 , "orgId" : 1 , "vitals" : 1 , "_id" : 1 , "processedDtTm" : 1 , "orgHierarchy" : 1 }, Sort: null
Also if I run explain:
> db.record.find({ "_id" : { "$in" : [ ObjectId("51ba0b43cb81e6b83acd9e6b") , ObjectId("51a8feb5cb8168350e373428") , ObjectId("51a90053cb8168350e373948") , ObjectId("51a901fecb8168350e373e82") , ObjectId("51a8f3e9cb8168350e3711d1") , ObjectId("51a8f3eacb8168350e3711d2") , ObjectId("51a8ff3ecb8168350e3735df") , ObjectId("51a8f59ecb8168350e37172b") , ObjectId("51a8f9aacb8168350e372418") , ObjectId("51a8f786cb8168350e371d42")]}}).explain();
{
"cursor" : "BtreeCursor _id_ multi",
"isMultiKey" : false,
"n" : 10,
"nscannedObjects" : 10,
"nscanned" : 18,
"nscannedObjectsAllPlans" : 10,
"nscannedAllPlans" : 18,
"scanAndOrder" : false,
"indexOnly" : false,
"nYields" : 0,
"nChunkSkips" : 0,
"millis" : 0,
"indexBounds" : {
"_id" : [
[
ObjectId("51a8f3e9cb8168350e3711d1"),
ObjectId("51a8f3e9cb8168350e3711d1")
],
[
ObjectId("51a8f3eacb8168350e3711d2"),
ObjectId("51a8f3eacb8168350e3711d2")
],
[
ObjectId("51a8f59ecb8168350e37172b"),
ObjectId("51a8f59ecb8168350e37172b")
],
[
ObjectId("51a8f786cb8168350e371d42"),
ObjectId("51a8f786cb8168350e371d42")
],
[
ObjectId("51a8f9aacb8168350e372418"),
ObjectId("51a8f9aacb8168350e372418")
],
[
ObjectId("51a8feb5cb8168350e373428"),
ObjectId("51a8feb5cb8168350e373428")
],
[
ObjectId("51a8ff3ecb8168350e3735df"),
ObjectId("51a8ff3ecb8168350e3735df")
],
[
ObjectId("51a90053cb8168350e373948"),
ObjectId("51a90053cb8168350e373948")
],
[
ObjectId("51a901fecb8168350e373e82"),
ObjectId("51a901fecb8168350e373e82")
],
[
ObjectId("51ba0b43cb81e6b83acd9e6b"),
ObjectId("51ba0b43cb81e6b83acd9e6b")
]
]
},
"server" : "ip-10-0-0-41:27017"
}
I turned on the profiler and this is what I get:
{
"op":"query",
"ns":"sytrue.record",
"query":{
"_id":{
"$in":[
ObjectId("51b1c98dcb81e4c1566b7436"),
ObjectId("51b1cb3ccb81e4c1566b79ab"),
ObjectId("51b1d741cb81e4c1566ba219"),
ObjectId("51b1caa8cb81e4c1566b77d4"),
ObjectId("51b1c98ccb81e4c1566b7433"),
ObjectId("51b1c691cb81e4c1566b6a8c"),
ObjectId("51b1cc21cb81e4c1566b7c9f"),
ObjectId("51b1c390cb81e4c1566b60c9"),
ObjectId("51b1d578cb81e4c1566b9c1d"),
ObjectId("51b1e13dcb81e4c1566bc30e")
]
}
},
"ntoreturn":0,
"ntoskip":0,
"nscanned":19,
"keyUpdates":0,
"numYield":0,
"lockStats":{
"timeLockedMicros":{
"r":NumberLong(380),
"w":NumberLong(0)
},
"timeAcquiringMicros":{
"r":NumberLong(2),
"w":NumberLong(4)
}
},
"nreturned":10,
"responseLength":36745,
"millis":0,
"ts": ISODate("2014-03-24T09:55:20.988 Z"),
"client":"127.0.0.1",
"allUsers":[
{
"user":"sytrue-user",
"userSource":"sytrue"
}
],
"user":"sytrue-user@sytrue"
}
- I also notice that when I retrieve individual record by its ID it is also slow (findOne method of PagingAndSortingRepository).
- I have to mention that I did not have this problem on the windows server.
- Please someone explain what's going on.
Update: I noticed that while the results are returned the CPU is consumed by the java code and not mongo server process. So the problem is either in the mongodb-java driver or spring-data-mongodb
I had the same issue. I have updated my spring framework from 4.0.0 to 4.0.3 and it worked !!!
Found the problem chatting with a MongoDB developer: I was running spring framework 4.0.0 and the slowness is related to this issue:
https://jira.spring.io/browse/SPR-11335
Updating Spring to version 4.0.1 (or above) solves the problem.
This was the stack trace from my call to the problem: