Why does MongoDB vary greatly in response time?

Question

MongoDB

MongoDB version: 2.6.3
There is a collection in which

{
"ns" : "common.searchResultForBasket",
"count" : 8798623,
"size" : 17425405456,
"avgObjSize" : 1980,
"storageSize" : 37209485088,
"numExtents" : 38,
"nindexes" : 3,
"lastExtentSize" : 2146426864,
"paddingFactor" : 1,
"systemFlags" : 1,
"userFlags" : 1,
"totalIndexSize" : 1480207568,
"indexSizes" : {
"_id_" : 399144144,
"uuid_1" : 684813584,
"date_1"
29 ,
"ok" :1
}

Here are the indexes:

{
"0" : {
"v" : 1,
"key" : {
"_id" : 1
},
"name" : "_id_",
"ns" : "common.searchResultForBasket"
},
"1" : {
"v " : 1,
"unique" : true,
"key" : {
"uuid" : NumberLong(1)
},
"name" : "uuid_1",
"ns" : "common.searchResultForBasket",
"sparse" : false
},
"2" : {
"v" : 1,
"key" : {
"date" : NumberLong(1)
},
"name" : "date_1",
"ns" : "common.searchResultForBasket",
"sparse" : false,
"expireAfterSeconds" : NumberLong(28800)
}
}

Вот пример запроса: db.searchResultForBasket.find({'uuid':'f4ee1c02-800b-43d0-b6ba-6f567e2bc9bd'})
Вот его explain:

{
"cursor" : "BtreeCursor uuid_1",
"isMultiKey" : false,
"n" : 1,
"nscannedObjects" : 1,
"nscanned" : 1,
"nscannedObjectsAllPlans" : 1,
"nscannedAllPlans" : 1,
"scanAndOrder" : false,
"indexOnly" : false,
"nYields" : 0,
"nChunkSkips" : 0,
"millis" : 0,
"indexBounds" : {
"uuid" : [
[
"f4ee1c02-800b-43d0-b6ba-6f567e2bc9bd",
" f4ee1c02-800b-43d0-b6ba-6f567e2bc9bd"
]
]
},
"server" : "mongodb02:27017",
"filterSet" : false,
"stats" : {
"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" : 1,
" yields" : 0,
"unyields" : 0,
"invalidates" : 0,
"advanced" : 1,
"needTime" : 0,
"needFetch" : 0,
"isEOF" : 1,
"keyPattern" : "{ uuid: 1 }",
"boundsVerbose" : "field #0['uuid']: [\"f4ee1c02-800b -43d0-b6ba-6f567e2bc9bd\", \"f4ee1c02-800b-43d0-b6ba-6f567e2bc9bd\"]",
"isMultiKey" : 0,
"yieldMovedCursor" : 0,
"dupsTested" : 0,
"dupsDropped" : 0,
" seenInvalidated" : 0,
"matchTested" : 0,
"keysExamined" : 1,
"children" : []
}
]
}
}

And so this find can be executed from 0.0001 to 6 seconds!!! :(
Where to dig? Why can there be such a scatter.
In this mong, the entire load goes only to this one collection. It is written to it about 5 times per second. It is read about 1 time per second.

Answer 1

So when you write, then it slows down: hint: How to avoid locking on big collection updates
+ don't forget about index rebuilding modes. If you are building on the fly, of course find will wait for the binary tree to increment.

Answer 2

If you are planning a large number of records in the collection and a small number of readings, then only replication. MongoDB was not designed to work in single server mode from birth. Minimum: 2 servers + 1 referee.
And then the recording will go to the primary, and you can force reading from the slave. Slave'u can also be forcibly prohibited from becoming primary.

Answer 3

There is an assumption that this IO "slows down", put some kind of io-monitor, and look at the moment of "brakes".
Once I observed a similar situation - one Linux process periodically raped the disk, while hammering IO.
Do you have ssh or regular storage?
The host must also have at least 2GB of RAM.

Answer 4

If there is no monitoring (custom or via MMS), I would start with mongostat .

xm:~$ mongostat -h d3.s1.fs.drive.bru:27021
connected to: d3.s1.fs.drive.bru:27021
insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       set repl       time
    *0     15     *0     *0       0     4|0       0  2590g  5183g  2.32g     14     a:0.1%          0       0|0     2|0     2k   426k   552 driveFS-1  PRI   13:20:00
    *0     17     *0     *0       0     4|0       0  2590g  5183g  2.33g     27     a:0.1%          0       0|0     0|0     4k   772k   552 driveFS-1  PRI   13:20:01
     1     10     *0     *0       2     6|0       0  2590g  5183g  2.33g     15     a:0.1%          0       0|0     0|0    18k   355k   552 driveFS-1  PRI   13:20:02
    *0     20      2     *0       0     4|0       0  2590g  5183g  2.33g     17     a:0.0%          0       0|0     0|0     3k   374k   552 driveFS-1  PRI   13:20:03
     1     14      2     *0       2     4|0       0  2590g  5183g  2.33g     21     a:3.3%          0       0|0     0|0   113k   690k   552 driveFS-1  PRI   13:20:04
    *0     11     *0     *0       0     3|0       0  2590g  5183g  2.32g     16     a:0.1%          0       0|0     0|0     2k   290k   552 driveFS-1  PRI   13:20:05

And then I would look into the MongoDB logs (if slowms is enabled) for long queries like:
Well, then I would try to correlate some page faults and so on in time with a slow request. One can connect dstat / iostat if the drive is suspected.