MongoDB v3.2.6 Спорадические медленные запросы
Может ли кто-нибудь дать представление о том, как устранить спорадическую медлительность, которую я испытываю с монго, или указать на какие-либо очевидные проблемы, основанные на моих журналах медленной работы?
У меня Mongo v3.2.6 с использованием движка WiredTiger, установленного на экземпляре m2.large (8 ГБ ОЗУ, 2 виртуальных ядра) ec2 под управлением сервера Ubuntu 14.04. На том же сервере установлен Java-процесс, который читает / пишет из / в процесс Монго, используя множество потоков. Нет никаких наборов реплик (я знаю, что должно быть), никаких проблем с памятью, которые я могу видеть, однако, у меня были спорадические медленные запросы, которые я не смог диагностировать.
Ниже приведен полный журнал от 21 июня 2016 года, в котором отображаются очень длинные запросы (более 10 секунд), которые обычно выполняются в течение нескольких миллисекунд.
2016-06-21T01: 27: 44.806ZI COMMAND [conn156] обновить запрос company.token: { _id: "1111" } update: { _id: "1111", _class: "company.domain.Token", userUUID: "5555", срок действия: 1466476050734 } keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keyUpdates:0 writeConflicts:0 numYields:1 блокировки:{ Global: { acquCount: { r: 2, w: 2 } }, База данных: {acquCount: { w: 2 } }, коллекция: {acquCount: { w: 2 } } } 14071мс 2016-06-21T01:27:44.806Z I COMMAND [conn151] обновить запрос company.token: { _id: "2222" } обновить: { _id: "2222", _class: "company.domain.Token", userUUID: "6666", срок действия истекает: 1466476050414 } keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keyUpdates:0 writeConflicts:0 numYields:1 locks:{ Global: { acquCount: { r: 2, w: 2 } }, База данных: {acquCount: { w: 2 } }, Коллекция: {acquCount: { w: 2 } } } 14391мс 2016-06-21T01:27:44.811Z I COMMAND [conn150] вставьте company.count вставлено:1 keyUpdates:0 writeConflicts:0 numYields:0 блокировок:{ Global: { acquCount: { r: 1, w: 1 } }, База данных: {acquCount: { w: 1 } }, коллекция: {acquCount: { w: 1 } } } 14074 мс 2016-06-21T01:39:45.807Z I COMMAND [conn151] обновить запрос company.token: { _id: "3333" } обновление: { _id: "3333", _class: "company.domain.Token", userUUID: "7777", срок действия истек: 1466476776277 } keysExamined:0 docsExamined:0 nMatched:1 nModified:1 upsert:1 keyUpdates:0 writeConflicts:0 numYields:0 блокировок:{ Global: { acquCount: {r: 1, w: 1}}, База данных: {acquCount: { w: 1 } }, Коллекция: {acquCount: { w: 1 } } } 9529ms
2016-06-21T10:34:14.596Z I COMMAND [conn156] команда company.count команда: aggregate {aggregate: "count", конвейер: [ { $match: { lId: "4444", $and: [ { iTS: { $gte: 1466475578989 } }, { iTS: { $lte: 1466505254467 } } ] } }, { $group: { _id: { rId: "$rId", sType: "$sType" }, количество: { $sum: "$rVal" } } } ] } keyUpdates:0 writeConflicts:0 numYields:92 reslen:162 блокировки:{ Global: { acquCount: { r: 190 } }, база данных: {acquCount: { r: 95 } }, Коллекция: {acquCount: { r: 95 } } } протокол:op_query 113ms
2016-06-21T10:39:17.113Z I COMMAND команда [conn146] команда company.count команда: aggregate {aggregate: "count", конвейер: [ { $match: { lId: "4444", $and: [ { iTS: { $gte: 1466475589300 } }, { iTS: { $lte: 1466505556971 } } ] } }, { $group: { _id: { rId: "$rId", sType: "$sType" }, count: { $sum: "$rVal" } } } ] } keyUpdates:0 writeConflicts:0 numYields:93 reslen:162 блокировки:{ Global: { acquCount: { r: 192 } }, база данных: {acquCount: { r: 96 } }, Коллекция: {acquCount: { r: 96 } } } протокол:op_query 141ms
2016-06-21T10:41:16.871Z I COMMAND [conn156] команда company.count команда: aggregate {aggregate: "count", конвейер: [ { $match: { lId: "4444", $and: [ { iTS: { $gte: 1466475578989 } }, { iTS: { $lte: 1466505676744 } } ] } }, { $group: { _id: { rId: "$rId", sType: "$sType" }, count: { $sum: "$rVal" } } } ] } keyUpdates:0 writeConflicts:0 numYields:94 reslen:162 блокировки:{ Global: { acquCount: { r: 194 } }, база данных: {acquCount: { r: 97 } }, столбец lection: { acquCount: { r: 97 } } } протокол:op_query 110msМедленные запросы, кажется, всегда update или же insert операции. Одна коллекция из приведенных выше таблиц медленных запросов company.token, он имеет ~55 тыс. документов со средним размером 160B. Эта коллекция читается очень часто (всплывает до 100 раз в секунду каждые 15 секунд). Запрос на чтение использует основной _id ключ для поиска, так что он попадает в индекс первичного ключа.
Другая коллекция из журнала company.count который содержит ~2,7 млн документов со средним размером 587 Б и записывается очень часто (пакеты по ~100 вставок в секунду каждые 15 секунд). Коллекция имеет устойчивые совокупные запросы на чтение (также показанные в журнале), выполняемые по отношению к коллекции, десятки в минуту. Совокупное чтение match предложение попадает в составной индекс и, кажется, никогда не сканирует больше документов, чем возвращается (executionStats показано внизу). Запросы на вставку, как правило, завершаются очень быстро, около 1-4 мс на вставку, однако один или два раза в день монго, кажется, заедает и занимает 10, иногда 20 секунд, для завершения быстрых операций.
Мое лучшее предположение о запаздывании связано с высокой степенью одновременной записи и чтения из двух коллекций из журнала, однако у меня сложилось впечатление, что WiredTiger использовал намеренные эксклюзивные и намеренные общие блокировки на уровне документа, которые должны обеспечивать высокий уровень параллелизма.
И последнее замечание: иногда я вижу другую коллекцию, которая содержит только один документ, для обновления которого требуется до 10 секунд, поэтому кажется, что, возможно, очередь записи и чтения исчерпана, так сказать, на глобальном уровне или на уровне базы данных. Есть ли способ подтвердить это?
{
"executionStats":{
"executionSuccess":true,
"nReturned":12006,
"executionTimeMillis":19,
"totalKeysExamined":12006,
"totalDocsExamined":12006,
"executionStages":{
"stage":"FETCH",
"nReturned":12006,
"executionTimeMillisEstimate":20,
"works":12007,
"advanced":12006,
"needTime":0,
"needYield":0,
"saveState":93,
"restoreState":93,
"isEOF":1,
"invalidates":0,
"docsExamined":12006,
"alreadyHasObj":0,
"inputStage":{
"stage":"IXSCAN",
"nReturned":12006,
"executionTimeMillisEstimate":0,
"works":12007,
"advanced":12006,
"needTime":0,
"needYield":0,
"saveState":93,
"restoreState":93,
"isEOF":1,
"invalidates":0,
"keyPattern":{
"lId":1,
"iTS":1
},
"indexName":"lId_1_iTS_1",
"isMultiKey":false,
"isUnique":false,
"isSparse":false,
"isPartial":false,
"indexVersion":1,
"direction":"forward",
"indexBounds":{
"lId":[
"[\"d4444\", \"4444\"]"
],
"iTS":[
"[1466475578989.0, 1466505676744.0]"
]
},
"keysExamined":12006,
"dupsTested":0,
"dupsDropped":0,
"seenInvalidated":0
}
}
}
}