Reputation: 2677
I am using meteor for one of my projects. I have a sporadic issue where sometimes one or two queries are taking very long time. For example, The following logs are taken from MongoDB logs, where the last part of each block mentions the time in milliseconds taken for query.
It can be seen that 4th and 5th logs show 14774ms and 17163ms respectively and other are almost 14-17 times lesser than these values. I can only see the IXSCAN
value changing from { value: 1 }
to { r.lid: 1 }
for the query which takes long time. After googling a little bit about IXSCAN
I came to know that it selects the indexes for scanning. I have the following questions,
[conn252] query cdk.WLCV query: { $query: { cid: "C1", uid: "W1", r.lid: "L12", value: { $gte: 1031, $lte: 1107 } }, orderby: { value: 1 } } planSummary: IXSCAN { value: 1 } ntoreturn:0 ntoskip:0 nscanned:59754 nscannedObjects:59754 keyUpdates:0 numYields:0 locks(micros) r:155165 nreturned:77 reslen:48530 155ms
[conn251] query cdk.WLCV query: { $query: { cid: "C2", uid: "W1", r.lid: "L12", value: { $gte: 1031, $lte: 1107 } }, orderby: { value: 1 } } planSummary: IXSCAN { value: 1 } ntoreturn:0 ntoskip:0 nscanned:59754 nscannedObjects:59754 keyUpdates:0 numYields:0 locks(micros) r:172445 nreturned:78 reslen:49160 172ms
[conn248] query cdk.WLCV query: { $query: { cid: "C3", uid: "W1", r.lid: "L12", value: { $gte: 1031, $lte: 1107 } }, orderby: { value: 1 } } planSummary: IXSCAN { value: 1 } ntoreturn:0 ntoskip:0 nscanned:59754 nscannedObjects:59754 keyUpdates:0 numYields:0 locks(micros) r:161176 nreturned:77 reslen:48222 161ms
[conn249] query cdk.WLCV query: { $query: { cid: "C4", uid: "W1", r.lid: "L12", value: { $gte: 1031, $lte: 1107 } }, orderby: { value: 1 } } planSummary: IXSCAN { r.lid: 1 } ntoreturn:0 ntoskip:0 nscanned:46147 nscannedObjects:46147 scanAndOrder:1 keyUpdates:0 numYields:11037 locks(micros) r:1384301 nreturned:77 reslen:48684 14774ms`
[conn250] query cdk.WLCV query: { $query: { cid: "C5", uid: "W1", r.lid: "L12", value: { $gte: 1031, $lte: 1107 } }, orderby: { value: 1 } } planSummary: IXSCAN { r.lid: 1 } ntoreturn:0 ntoskip:0 nscanned:46147 nscannedObjects:46147 scanAndOrder:1 keyUpdates:0 numYields:9464 locks(micros) r:1904782 nreturned:77 reslen:48761 17163ms
[conn249] query cdk.WLCV query: { $query: { cid: "C6", uid: "W1", r.lid: "L12", value: { $gte: 790, $lte: 940 } }, orderby: { value: 1 } } planSummary: IXSCAN { r.lid: 1 } cursorid:305719783659 ntoreturn:0 ntoskip:0 nscanned:46147 nscannedObjects:46147 scanAndOrder:1 keyUpdates:0 numYields:0 locks(micros) r:114383 nreturned:101 reslen:63650 114ms`
[conn250] query cdk.WLCV query: { $query: { cid: "C7", uid: "W1", r.lid: "L12", value: { $gte: 790, $lte: 940 } }, orderby: { value: 1 } } planSummary: IXSCAN { r.lid: 1 } cursorid:305713399194 ntoreturn:0 ntoskip:0 nscanned:46147 nscannedObjects:46147 scanAndOrder:1 keyUpdates:0 numYields:0 locks(micros) r:105275 nreturned:101 reslen:63246 105ms
[conn251] query cdk.WLCV query: { $query: { cid: "C8", uid: "W1", r.lid: "L12", value: { $gte: 790, $lte: 940 } }, orderby: { value: 1 } } planSummary: IXSCAN { r.lid: 1 } cursorid:306335307165 ntoreturn:0 ntoskip:0 nscanned:46147 nscannedObjects:46147 scanAndOrder:1 keyUpdates:0 numYields:0 locks(micros) r:134425 nreturned:101 reslen:63650 134ms
[conn252] query cdk.WLCV query: { $query: { cid: "C9", uid: "W1", r.lid: "L12", value: { $gte: 790, $lte: 940 } }, orderby: { value: 1 } } planSummary: IXSCAN { r.lid: 1 } cursorid:306643211432 ntoreturn:0 ntoskip:0 nscanned:46147 nscannedObjects:46147 scanAndOrder:1 keyUpdates:0 numYields:0 locks(micros) r:143227 nreturned:101 reslen:63650 143ms
Following are the db stats that I got from mongo console.
{
"ns" : "cdk.WLCV",
"count" : 8891054,
"size" : 8962182432,
"avgObjSize" : 1008,
"storageSize" : 9305935856,
"numExtents" : 25,
"nindexes" : 8,
"lastExtentSize" : 2146426864,
"paddingFactor" : 1,
"systemFlags" : 1,
"userFlags" : 1,
"totalIndexSize" : 3600456944,
"indexSizes" : {
"_id_" : 544161856,
"uid_1" : 612635856,
"cid_1" : 357135856,
"r.lid_1" : 484370768,
"r.m" : 366898000,
"value_1" : 318700480,
"mvalue_1" : 359400608,
"r.did_1" : 557153520
},
"ok" : 1
}
Upvotes: 0
Views: 145