Почему у MongoDB сильно варьируется время ответа?

Question

[Дмитрий Лабутин]

MongoDB version: 2.6.3
Есть коллекция, в которой

{
"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" : 396249840
},
"ok" : 1
}

Вот индексы:

{
"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" : []
}
]
}
}

Так вот этот find может выполняться от 0.0001 сек до 6 секунд!!! :(
Куда копать? Почему может быть такой разброс.

В этой монге вся нагрузка идет только на эту одну коллекцию. В нее пишется примерно 5 раз в секунду. Читается примерно 1 раз в секунду.

Answer 1

[xSkyFoXx]

Так когда пишите, тогда и тормозится: hint: How to avoid locking on big collection updates

+ не забывайте про режими перестройки индекса. Если строите "на лету", конечно же find будет ожидать инкремента бинарного дерева.

Comments

[Дмитрий Лабутин]

У нас пишется постоянно. А тормозит периодически. Больше похоже на перестройку индекса?

[xSkyFoXx]

Мне кажется да, но это уже субъективно. Чтобы быть уверенным надо играться вашим датасетом.

[xSkyFoXx]

Можно, конечно, делать выборку по значениям вне индекса... Это будет работать за линейное время от размера коллекции - но судя по вашим объёмам это очень и очень плохая идея.

[Дмитрий Лабутин]

Да, без индекса там на минуты идет время. Это не вариант.

Answer 2

[Виталий Ф.]

Если вы планируете большое кол-во записей в коллекцию и малое кол-во чтений - то только репликация. MongoDB с рождения не был рассчитан на работу в режиме одиночного сервера. Минимум: 2 сервера + 1 арбитр.

И тогда запись будет идти на primary, а читать можно принудительно со slave. Slave'у можно так же принудительно запретить становится primary.

Answer 3

[lega]

Есть предположение что это IO "тормозит", поставте какой-нибуть io-монитор, и посмотрите на момент "тормозов".
Однажды наблюдал подобную ситуацию - один линуксовый процесс периодический насиловал диск, при этом забивал IO.
У вас на ssh или обычное хранилище?
Так же на хосте должно быть как минимум 2Гб оперативы.

Answer 4

[Аристарх Загородников]

Если нет мониторинга (кастомного или через MMS), я бы начал с 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

А потом бы посмотрел в логи MongoDB (если включён slowms) на предмет длинных запросов вроде:

2015-01-24T13:18:26.824+0300 [conn121317] query a.fs.chunks query: { query: { files_id: 2318948981658353664, n: 0 }, $readPreference: { mode: "nearest", tags: [ { group: "d2" }, {} ] } } planSummary: IXSCAN { files_id: 1, n: 1 } ntoreturn:2 ntoskip:0 nscanned:1 nscannedObjects:1 keyUpdates:0 numYields:1 locks(micros) r:126010 nreturned:1 reslen:52407 599ms

Ну и дальше попробовал бы скоррелировать какие нибудь page fault и прочее по времени с медленным запросом. Можно подключить dstat/iostat, если есть подозрение на диск.