В db.serverStatus().wiredTiger.cache копятся грязные байты, потоки вытеснения переписывают страницы на диск, а explain выбирает не тот индекс, что ждал разработчик. За этим стоит одна машина. Документ хранится как BSON, где у каждого поля есть длина. WiredTiger держит страницы b-tree в кэше вместе с цепочками обновлений и пишет их на диск двумя путями: при вытеснении и в checkpoint. Журнал защищает записи между checkpoint, а планировщик выбирает индекс пробным запуском всех кандидатов. Версии записи в цепочке и history store разобраны в статье про старые версии строк, а checkpoint и fsync в PostgreSQL — в статьях про checkpoint и всплески I/O и путь записи до диска. Репликация и шардирование MongoDB — в отдельной статье.
WiredTiger: страница в памяти, reconciliation, checkpoint и журнал
__wt_reconcile: при вытеснении под давлением грязных байт или в checkpoint по таймеру. Между checkpoint записи защищает журнал, который сбрасывается каждые 100 мс.Стенд
Контейнер с кэшем WiredTiger 0,25 ГБ, чтобы давление на кэш проявилось на сотнях мегабайт. Каждый скрипт ниже сохрани в файл, скопируй в контейнер (docker cp <файл> dba-mongodb-wiredtiger-architecture:/tmp/) и запусти через docker exec dba-mongodb-wiredtiger-architecture mongosh --quiet /tmp/<файл>:
docker run -d --name dba-mongodb-wiredtiger-architecture --memory 2g mongo:8 --wiredTigerCacheSizeGB 0.25
docker exec dba-mongodb-wiredtiger-architecture mongosh --quiet --eval 'print(db.version(), db.serverStatus().wiredTiger.uri)'
docker exec dba-mongodb-wiredtiger-architecture mongosh --quiet --eval 'printjson(db.adminCommand({getParameter:1, syncdelay:1, journalCommitInterval:1}))'вывод
8.3.13 statistics: WiredTiger 12.0.0: (November 15, 2024)
{ syncdelay: 60, journalCommitInterval: 100, ok: 1 }Код сверен по тегу r8.3.13, совпадающему с db.version(). gitVersion собранного образа (3b8a5e1f…) в публичном репозитории не нашёлся, поэтому строки кода сверены по тегу, а не по этому хешу. Числа 60 и 100 подтверждаются getParameter выше, документацией и кодом: journalCommitIntervalMs{100} в storage_options.h и описание syncdelay («every 60 seconds») в storage_parameters.idl.
BSON, страница коллекции и пороги кэша
Документ — последовательность элементов: байт типа, имя поля с нулём на конце и значение. Первые четыре байта документа — его общая длина, последний байт — ноль. Размер видно прямо. Вторую и третью команды запускай после опыта 1: им нужна коллекция lab.t и кэш под нагрузкой.
for (const d of [{}, { a: 1 }, { a: 1, s: "hi" }, { a: 1.5 }]) print(JSON.stringify(d), "->", bsonsize(d), "байт");
const t = db.getSiblingDB("lab").t;
print(t.stats().wiredTiger.creationString.split(",").filter(x => /^(leaf_page_max|memory_page_max|block_compressor|key_format|value_format)/.test(x)).join(" "));
const th = db.serverStatus().wiredTiger.cache, p = (k) => th["eviction threshold " + k + " multiplied by 100 for precision"] / 100;
print("кэш, МиБ:", th["maximum bytes configured"] / 1048576, " dirty target/trigger, %:", p("dirty target"), p("dirty trigger"), " cache target/trigger, %:", p("cache full target"), p("cache full trigger"));вывод
{} -> 5 байт
{"a":1} -> 12 байт
{"a":1,"s":"hi"} -> 22 байт
{"a":1.5} -> 16 байт
block_compressor=snappy key_format=q leaf_page_max=32KB memory_page_max=10M value_format=u
кэш, МиБ: 256 dirty target/trigger, %: 5 20 cache target/trigger, %: 80 95Пустой документ — 5 байт: длина и завершающий ноль. {a: 1} — 12: к ним добавились тип (1), имя a с нулём (2) и int32 (4). Строка "hi" стоит 10 байт: тип, имя, длина строки (4), два символа и ноль. Двойное число 1.5 занимает 8 байт вместо 4, поэтому документ выходит на 16. Строка с key_format — как WiredTiger хранит коллекцию: ключ q (64-битное целое, у коллекции это RecordId), значение u (BSON как есть), лист на диске не больше 32 КБ (leaf_page_max), страница в памяти растёт до 10 МБ (memory_page_max), сжатие snappy. Последняя строка — пороги вытеснения. По документации WiredTiger memory_page_max — размер, до которого страница может вырасти в памяти до записи на диск.
Опыт 1: запись, грязные байты и вытеснение
Скрипт вставляет 1,2 млн документов пачками по 5 000 в коллекцию с индексом по user (1 000 значений). Кэш 256 МиБ, а данные плюс индекс заметно больше. Каждые 100 000 документов скрипт печатает грязные байты, размер кэша, число вытесненных изменённых и неизменённых страниц и число checkpoint:
const w = () => db.serverStatus().wiredTiger;
const row = (t0, docs) => { const s = w(), k = s.cache;
return [((Date.now()-t0)/1000).toFixed(0).padStart(4), String(docs).padStart(8),
(k["tracked dirty bytes in the cache"]/1048576).toFixed(1).padStart(7),
(k["bytes currently in the cache"]/1048576).toFixed(1).padStart(7),
String(k["modified pages evicted"]).padStart(7), String(k["unmodified pages evicted"]).padStart(7),
String(s.checkpoint["total succeed number of checkpoints"]).padStart(5)].join(" "); };
const d = db.getSiblingDB("lab"); d.dropDatabase();
d.t.createIndex({ user: 1 });
const pool = []; for (let i = 0; i < 2000; i++) pool.push(Math.random().toString(36).slice(2) + Math.random().toString(36).slice(2));
print(" с докум. dirtyМБ кэшМБ evict_m evict_u ckpt");
const t0 = Date.now(); print(row(t0, 0));
const N = 1200000, B = 5000;
for (let n = 0; n < N; n += B) {
const docs = []; for (let i = 0; i < B; i++) { const x = n + i;
docs.push({ n: x, user: x % 1000, status: x % 5, pad: pool[x % 2000] + pool[(x*7) % 2000] + pool[(x*13) % 2000] + pool[(x*29) % 2000] + pool[(x*31) % 2000] + pool[(x*37) % 2000] }); }
d.t.insertMany(docs, { ordered: false });
if ((n + B) % 100000 == 0) print(row(t0, n + B));
}
print("итог:", JSON.stringify({ count: d.t.countDocuments(), dataMB: +(d.t.stats().size/1048576).toFixed(1), storageMB: +(d.t.stats().storageSize/1048576).toFixed(1), indexMB: +(d.t.stats().totalIndexSize/1048576).toFixed(1) }));вывод
с докум. dirtyМБ кэшМБ evict_m evict_u ckpt
0 0 0.0 0.1 0 0 0
1 100000 15.1 22.2 42 0 0
1 200000 9.7 27.0 407 0 0
2 300000 15.0 43.0 775 0 0
2 400000 27.0 65.7 1310 0 0
3 500000 20.0 71.5 2587 0 0
3 600000 17.5 84.2 3787 0 0
4 700000 16.7 95.1 5533 0 0
4 800000 34.5 117.8 7409 0 0
5 900000 22.3 127.8 12739 0 0
6 1000000 26.6 154.4 19786 0 0
7 1100000 24.3 177.6 26151 0 0
7 1200000 28.7 204.2 33901 0 0
итог: {"count":1200000,"dataMB":217.6,"storageMB":159.9,"indexMB":20.1}Пороги вытеснения из последней строки вывода выше: грязные данные — цель 5 % кэша (12,8 МиБ) и порог 20 % (51,2 МиБ), весь кэш — цель 80 % (204,8 МиБ) и порог 95 %. Таблица читается по ним:
- Грязных байт 10–35 МиБ: выше цели 5 %, ниже порога 20 %. Вытеснение изменённых страниц идёт,
evict_mрастёт до 33 901. evict_uравен нулю всё время: неизменённые страницы не вытесняются, пока кэш не дойдёт до цели 80 %. Кэш подошёл к этой цели (204,2 из 204,8 МиБ) только в последней строке.- 217,6 МБ BSON заняли на диске 159,9 МБ, индекс — 20,1 МБ: так выглядит сжатие snappy.
- checkpoint за 7 секунд не было: счётчик остался нулём. Вытеснение шло само, без таймера.
Откуда эти 33 901 вытеснение? Статистика по таблице и по индексу:
const s = db.getSiblingDB("lab").t.stats({ indexDetails: true });
print("коллекция: modified evicted =", s.wiredTiger.cache["modified pages evicted"], " pages written =", s.wiredTiger.cache["pages written from cache"]);
const i = s.indexDetails.user_1.cache;
print("индекс user_1: modified evicted =", i["modified pages evicted"], " pages written =", i["pages written from cache"]);
print("сервер: modified evicted =", db.serverStatus().wiredTiger.cache["modified pages evicted"]);вывод
коллекция: modified evicted = 161 pages written = 4615
индекс user_1: modified evicted = 34194 pages written = 32566
сервер: modified evicted = 34461Почти всё вытеснение — страницы индекса: 34 194 из 34 461 по серверу, у коллекции 161. Объяснение следует из ключей: коллекция растёт по возрастающему RecordId, то есть пишется в правый край дерева. В индексе user 1 000 групп ключей, и каждая принимает свои вставки, поэтому грязными становятся листья по всему дереву. Это чтение чисел, а не отдельное измерение механизма.
Вытеснение и checkpoint записывают страницу одной функцией (__wt_reconcile, тег r8.3.13). Она собирает из страницы с цепочками WT_UPDATE образ для диска; причина записи видна в отладочном сообщении:
/*
* __wt_reconcile --
* Reconcile an in-memory page into its on-disk format, and write it.
*/
int
__wt_reconcile(WT_SESSION_IMPL *session, WT_REF *ref, WT_SALVAGE_COOKIE *salvage, uint32_t flags)
...
__wt_verbose_debug1(session, WT_VERB_RECONCILE, "%p reconcile %s (%s%s)", (void *)ref,
__wt_page_type_string(page->type), LF_ISSET(WT_REC_EVICT) ? "evict" : "checkpoint",
LF_ISSET(WT_REC_HS) ? ", history store" : "");Пропущены строки 33–41. Флаг WT_REC_EVICT отличает запись при вытеснении от записи в checkpoint (строки 42–44), а WT_REC_HS добавляет к сообщению пометку «history store».
Опыт 2: checkpoint и журнал
Два вопроса: правда ли checkpoint идёт раз в 60 секунд и журнал сбрасывается раз в 100 мс. Скрипт пишет 130 секунд по 2 000 документов в секунду и фиксирует момент, когда растёт счётчик checkpoint, а затем сравнивает вызовы log flush и log sync:
const w = () => db.serverStatus().wiredTiger, d = db.getSiblingDB("lab");
const s0 = w(), t0 = Date.now();
let prev = s0.checkpoint["total succeed number of checkpoints"], x = 5000000;
for (let sec = 1; sec <= 130; sec++) {
const docs = []; for (let i = 0; i < 2000; i++, x++) docs.push({ n: x, user: x % 1000, status: x % 5, pad: "p" + x });
d.t.insertMany(docs);
const c = w().checkpoint["total succeed number of checkpoints"];
if (c != prev) { print("t=" + sec + " с: checkpoint " + prev + " -> " + c + ", " + w().checkpoint["most recent time (msecs)"] + " мс"); prev = c; }
sleep(Math.max(0, sec * 1000 - (Date.now() - t0)));
}
const s1 = w();
print("за " + ((Date.now() - t0) / 1000).toFixed(0) + " с: log flush", s1.log["log flush operations"] - s0.log["log flush operations"], " log sync", s1.log["log sync operations"] - s0.log["log sync operations"]);вывод
t=16 с: checkpoint 7 -> 8, 95 мс
t=76 с: checkpoint 8 -> 9, 103 мс
за 130 с: log flush 1288 log sync 216Два checkpoint с разницей 60 секунд по секундным отметкам скрипта, каждый занял около 0,1 с (на этом объёме грязных данных). Счётчик начинается не с нуля: контейнер к этому моменту уже работал. Вызовов log flush 1 288 за 130 секунд — около десяти в секунду, то есть раз в 100 мс; fsync (log sync) выполняется реже, 216 раз. Код Checkpointer ждёт syncdelay секунд после завершения предыдущего checkpoint, поэтому период — 60 секунд плюс длительность самого checkpoint:
// Wait for 'storageGlobalParams.syncdelay' seconds; or until either shutdown is
// signaled or a checkpoint is triggered.
...
_sleepCV.wait_for(lock,
stdx::chrono::seconds(
static_cast<std::int64_t>(storageGlobalParams.syncdelay.load())),
[&] { return _shuttingDown || _triggerCheckpoint; });(Checkpointer::run, строки 100–104 с логированием пропущены; комментарий к syncdelay говорит о паузе «после завершения предыдущего».) Журнал сбрасывает отдельный поток: в JournalFlusher::run срок следующего сброса равен Date_t::now() + Milliseconds(storageGlobalParams.journalCommitIntervalMs.load()), и поток просыпается раньше, если кто-то запросил сброс немедленно. Так делает запись с j: true. Следующий скрипт сравнивает 200 вставок по одной с j: false и j: true:
const w = () => db.serverStatus().wiredTiger;
const j = db.getSiblingDB("lab").j; j.drop();
for (const wc of [{ w: 1, j: false }, { w: 1, j: true }]) {
const a = w(), t = Date.now();
for (let i = 0; i < 200; i++) j.insertOne({ i: i }, { writeConcern: wc });
const ms = Date.now() - t, b = w();
print(JSON.stringify(wc), "200 вставок:", ms, "мс; log sync:", b.log["log sync operations"] - a.log["log sync operations"], " log flush:", b.log["log flush operations"] - a.log["log flush operations"]);
}вывод
{"w":1,"j":false} 200 вставок: 111 мс; log sync: 3 log flush: 1
{"w":1,"j":true} 200 вставок: 1069 мс; log sync: 200 log flush: 200Запись j: true не ждёт такта в 100 мс: 200 вставок прошли за 1 069 мс при 200 fsync, то есть каждая вставка получила свой сброс, в среднем по 5,3 мс. Время зависит от диска: в трёх прогонах этого скрипта было 370, 467 и 1 069 мс, а число fsync каждый раз равнялось 200. С j: false те же 200 вставок заняли 111 мс и 3 fsync: подтверждение уходит до сброса журнала, и до следующего такта (по документации — каждые 100 мс) запись может быть только в памяти.
Опыт 3: планировщик выбирает по пробному запуску
На той же коллекции два индекса, user_1 и status_1, и запрос по обоим полям. status принимает 5 значений, user — 1 000, и все 1 200 документов с user: 7 имеют status: 2. Скрипт печатает план из explain("allPlansExecution") и запись в кэше планов:
const t = db.getSiblingDB("lab").t;
t.createIndex({ status: 1 });
const q = { user: 7, status: 2 };
const show = (e) => {
const ex = e.executionStats, w = e.queryPlanner.winningPlan;
const stage = (p) => p.stage + (p.indexName ? "(" + p.indexName + ")" : "") + (p.inputStage ? " > " + stage(p.inputStage) : "");
print("winningPlan: ", stage(w));
e.queryPlanner.rejectedPlans.forEach((p) => print("rejectedPlans:", stage(p)));
print("nReturned:", ex.nReturned, " keysExamined:", ex.totalKeysExamined, " docsExamined:", ex.totalDocsExamined);
(ex.allPlansExecution || []).forEach((p) => { const s = p.executionStages; print(" кандидат", stage(s), " works=" + s.works, "advanced=" + s.advanced, "isEOF=" + s.isEOF); });
};
print("--- индексы user_1 и status_1");
show(t.find(q).explain("allPlansExecution"));
print("--- planCache после запуска");
t.find(q).itcount(); t.find(q).itcount();
t.aggregate([{ $planCacheStats: {} }]).forEach((e) => print("кэш плана: isActive=" + e.isActive, "works=" + e.works, "индекс=" + e.cachedPlan.inputStage.indexName, "запрос=" + JSON.stringify(e.createdFromQuery.query)));вывод
--- индексы user_1 и status_1
winningPlan: FETCH > IXSCAN(user_1)
rejectedPlans: FETCH > IXSCAN(status_1)
nReturned: 1200 keysExamined: 1200 docsExamined: 1200
кандидат FETCH > IXSCAN(user_1) works=101 advanced=101 isEOF=0
кандидат FETCH > IXSCAN(status_1) works=101 advanced=1 isEOF=0
--- planCache после запуска
кэш плана: isActive=true works=101 индекс=user_1 запрос={"user":7,"status":2}Оба кандидата отработали по 101 шагу (works) и остановились: пробный запуск заканчивается, когда один из планов вернул 101 результат (internalQueryPlanEvaluationMaxResults = 101 по умолчанию; лимит шагов internalQueryPlanEvaluationWorks = 10 000). Дальше план оценивается долей «продвинутых» шагов (advanced из works):
double calculateProductivity(const PlanStageStats* stats) const final {
tassert(
11321201, "Expected plan stats works to be greater than 0", stats->common.works != 0);
return static_cast<double>(stats->common.advanced) /
static_cast<double>(stats->common.works);
}(plan_ranker.cpp.) У user_1 это 101/101, у status_1 — 1/101: в первых 101 шаге обхода документов со status: 2 под user: 7 попал один. Победитель попал в кэш планов вместе с works=101.
Что из этого следует
- Каждый вторичный индекс — ещё одно дерево в кэше. В опыте 1 на 1,2 млн вставок коллекция дала 161 вытеснение изменённых страниц, индекс по
user— 34 194. Индекс с разбросанными ключами делает запись дороже самой коллекции. - Следи за
tracked dirty bytes in the cacheотносительно 5 % и 20 % кэша (12,8 и 51,2 МиБ при кэше 256 МиБ) и заmodified pages evicted: это счётчики того, что дальше уйдёт на диск. w: 1безjподтверждает запись до сброса журнала, окно — доjournalCommitInterval(100 мс).j: trueна каждую вставку стоитfsyncна каждую (200 из 200); подтверждение с журналом дешевле запрашивать на пачку документов, чем на каждый; что к этому добавляетw: majority, разобрано в статье про репликацию.- Читай
allPlansExecution, а не толькоwinningPlan: поadvanced/worksвидно, насколько победитель оторвался отrejectedPlans(101/101 против 1/101). - Лицензия сервера — SSPL. Раздел 13 требует открыть исходный код сервиса тем, кто предлагает функциональность MongoDB третьим лицам как сервис; в тексте среди примеров — удалённое взаимодействие с ней по сети. Спорные случаи разбирает юрист.
Чек-лист
- Выведи
db.serverStatus().wiredTiger.cacheна рабочей нагрузке и сравниtracked dirty bytes in the cacheс 5 % и 20 % отmaximum bytes configured. - Для самого записываемого индекса сравни
modified pages evictedпоstats({indexDetails: true})с коллекцией: найди индексы, которые дают основной объём. - Проверь
db.adminCommand({getParameter: 1, syncdelay: 1, journalCommitInterval: 1}): значения 60 и 100 менять не нужно: документация просит оставить 60 и предупреждает, что при 0 журнал со временем займёт весь диск. - Для медленных запросов смотри
explain("allPlansExecution"): если у победителя и отвергнутых планов близкиеadvanced/works, выбор неустойчив. - Убери стенд вместе с томом:
docker rm -f -v dba-mongodb-wiredtiger-architecture.