Инвалидация кеша шла 40 минут, и всё это время цены были вчерашние

MAATRIX

В 7:12 утра в саппорт прилетел первый тикет: «купил товар по одной цене, а в личном кабинете и в чеке — другая». К 7:40 всё само пришло в норму, но за эти неполные полчаса магазин успел продать несколько десятков позиций по вчерашним, уже неактуальным ценам — часть дешевле новых, часть дороже. Ночной пересчёт цен отработал штатно и без ошибок в логах, кеш физически обновился — но между «обновился в базе» и «стал виден на витрине» пролегли те самые 40 минут, которые никто не закладывал в план акции. Дальше — как это выглядело в мониторинге, какие версии проверяли и отбрасывали, и в чём была настоящая причина.

Что видели в мониторинге в первые минуты

Витрина интернет-магазина берёт цену из Redis по ключу вида price:{sku_id}, TTL ключа — сутки, но полагаться на TTL никто не собирался: сразу после пересчёта цен в ночном батче отдельный воркер обязан явно инвалидировать ключи изменившихся товаров. Ночью прошёл сезонный пересчёт по нескольким тысячам SKU — часть цен снизилась в рамках акции, часть выросла из-за курса у поставщиков.

Первое, на что посмотрели, — dashboard самого price-service в Grafana. Картина была такая:

• очередь событий инвалидации (price.invalidate, RabbitMQ) подскочила с нуля до нескольких десятков тысяч сообщений почти мгновенно, в момент завершения батч-джобы в 03:02;
• очередь спадала линейно и монотонно, без провалов и без ретраев, и дошла до нуля примерно к 03:41 — то есть ровно те самые ~40 минут;
• CPU и память у Redis — в норме, никаких скачков;
• cache hit ratio на витрине держался около 99% всё это время — то есть кеш прекрасно работал, просто отдавал не то.

Именно последний пункт сбивал с толку в первые минуты: если бы кеш массово промахивался или падал, это было бы видно сразу — ошибки, рост латентности, алерты. А тут всё «зелёное», кроме того, что цены неправильные. Классическая ловушка: метрика «кеш здоров» и метрика «данные в кеше актуальны» — это две разные вещи, и обычный дашборд первую видит, а вторую нет.

Гипотезы, которые отбросили

По горячим следам разобрали пять версий, и все оказались мимо.

Реплика Redis отстаёт от мастера. Если читающий трафик частично уходит на реплику, а инвалидация идёт через мастер, отставание репликации объяснило бы устаревшие данные. Проверили INFO replication на реплике — master_repl_offset и slave_repl_offset расходились на считаные байты, отставание было в пределах миллисекунд. Не то.

CDN-кеш на edge не сброшен. Часть карточек товара кешируется на CDN на короткое время. Проверили заголовки Cache-Control и историю purge-запросов к CDN — TTL на edge выставлен в 60 секунд, purge отработал штатно в первую минуту после пересчёта. CDN подозрение сняли быстро — 60 секунд никак не превращаются в 40 минут.

Воркер инвалидации вообще не запустился, обновляет цены кто-то другой. Проверили systemd-юнит воркера — процесс жил всё это время, PID не менялся, логи писались равномерно, каждая обработанная запись подтверждалась. Воркер работал — просто медленно.

Рассинхрон версий ключей после недавнего деплоя. За неделю до инцидента выкатывали правку в price-service — была версия, что новый код пишет по одному формату ключа, а читает витрина по другому, из-за чего инвалидация якобы «мажет мимо». Сравнили ключи напрямую через redis-cli --scan --pattern 'price:*' — формат совпадал один в один что у писателя, что у читателя.

Гонка между коммитом транзакции и публикацией события. Была мысль, что событие инвалидации публикуется до того, как транзакция с новой ценой закоммитилась в Postgres, и воркер читает ещё старое значение. Проверили код — публикация в очередь стоит строго после COMMIT, гонки на уровне транзакции не было. К тому же это объяснило бы единичные несовпадения, а не растянутую на 40 минут задержку у всего каталога разом.

Каждая из этих версий по отдельности выглядела правдоподобно и заняла бы недели полторы часа на полноценную проверку каждая — если бы шли по ним последовательно, а не параллельно. Разбор ускорило именно то, что сразу считали числа, а не гадали.

Как нашли настоящую причину

Переломный момент — когда сопоставили две цифры. Число сообщений на пике очереди (чуть больше 24 000) оказалось практически равно количеству SKU, у которых в эту ночь изменилась цена. А время полного опустошения очереди (40 минут = 2400 секунд) поделили на это количество сообщений — получилось около 0,1 секунды на одно сообщение, с очень маленьким разбросом.

Такая ровная, «часовая» скорость обработки — это почти всегда признак не перегрузки (перегрузка даёт скачки и ретраи), а искусственного ограничения прямо в коде. Пошли смотреть воркер инвалидации:

def process_invalidation(sku_id: str) -> None:
    redis_client.delete(f"price:{sku_id}")
    time.sleep(0.1)  # troubleshoot: защита Redis от перегрузки массовым DEL, см. INC-114

git blame на эту строку вывел на коммит полугодовой давности со ссылкой на прошлый инцидент: тогда массовая инвалидация без паузы укладывала Redis в затяжной event-loop-затор — команды DEL выполняются в один поток, и залповая пачка из пары тысяч операций подряд ощутимо поднимала latency у всех остальных запросов к тому же инстансу. Тогдашнее решение — воткнуть sleep(0.1) между вызовами — сняло проблему за несколько секунд, потому что каталог в тот момент насчитывал около 2000 SKU: 2000 × 0,1 с ≈ 200 секунд, немного за три минуты, и на это тогда никто не обратил внимания как на проблему.

За полгода ассортимент вырос примерно в 10 раз (расширили каталог, добавили несколько новых категорий), количество единовременно обновляемых цен выросло пропорционально — а троттлинг остался прежним, потому что никто не привязывал его к размеру каталога и не пересматривал при расширении ассортимента. 24 000 × 0,1 с ≈ 2400 секунд — это и есть те самые 40 минут, минута в минуту.

Архитектура инвалидации: где был реальный затык

Стоит разложить по шагам, что происходило physически, потому что сам механизм был спроектирован разумно — подвела только фиксированная задержка, вшитая в него как «временная» мера.

1. Ночной батч пересчитывает цены в Postgres и коммитит изменения пачками.
2. После коммита каждой пачки в очередь публикуется событие price.invalidate с sku_id.
3. Один воркер-консьюмер читает очередь строго последовательно, по одному сообщению.
4. На каждое сообщение — вызов DEL к Redis и sleep(0.1).
5. Витрина при промахе кеша читает актуальную цену из Postgres и кладёт её обратно в Redis.

Узкое место — шаги 3 и 4: однопоточный консьюмер с фиксированной паузой, которая когда-то была правильным компромиссом, а с ростом каталога превратилась в жёсткий потолок пропускной способности, никак не связанный с реальной нагрузочной способностью Redis. При этом сам Redis всё это время скучал — CPU и память были в норме, он бы спокойно переварил инвалидацию в разы быстрее.

Отдельно стоит подчеркнуть: DEL по одному ключу за раз — само по себе не оптимальный способ массовой инвалидации, даже без искусственной паузы. Пакетное удаление через pipeline или UNLINK (асинхронное удаление, не блокирующее event loop) обходится Redis заметно дешевле, чем то же количество отдельных round-trip'ов по сети.

Что изменили после разбора

• Убрали sleep() из воркера и заменили точечные DEL на пакетные операции: события копятся окном в несколько сотен миллисекунд, ключи одной пачки удаляются через pipeline с UNLINK.
• Вместо одного консьюмера подняли consumer group из нескольких воркеров, разбирающих очередь параллельно; обработка сообщения сделана идемпотентной (повторный UNLINK несуществующего ключа безопасен), так что параллелизм не грозит гонками.
• Ограничение нагрузки на Redis больше не завязано на фиксированную паузу «на глазок» — вместо неё в воркере есть предел размера батча за один pipeline-запрос и мониторинг реальной латентности команд через redis-cli --latency-history и slowlog, а не выдуманная константа.
• Добавили два алерта, которых раньше не было: глубина очереди инвалидации (price.invalidate) сверх порога и возраст самого старого необработанного события в ней — раньше был только алерт на общую доступность очереди, а не на то, сколько событие в ней «протухает».
• Ввели версионирование ключей кеша (price:v{n}:{sku_id}): при массовом обновлении переключение версии для читателей происходит одним атомарным изменением, а старые ключи просто вымирают по TTL, без необходимости физически удалять тысячи записей синхронно. Это не отменяет точечную инвалидацию (она нужна для единичных изменений цены вне батча), но снимает нагрузку с неё в сценарии массового пересчёта.
• В рантбуке по инцидентам появился пункт: любое временное ограничение вида «пауза между операциями» или «искусственный троттлинг» заводится с датой пересмотра и тикетом на календаре, а не остаётся в коде бессрочно с комментарием «см. INC-114».

Как спроектировать инвалидацию кеша, чтобы не наступить на те же грабли

Несколько выводов, которые стоит применить заранее, а не после похожего разбора:

• Не тормозите инвалидацию искусственной паузой. Если Redis реально не тянет залповую нагрузку — ограничивайте размер батча в pipeline и используйте UNLINK вместо DEL, а не вставляйте sleep() между вызовами. Пауза не масштабируется вместе с ростом данных, а лимит батча — масштабируется.
• Версионируйте ключи для массовых обновлений. Для точечных изменений (одна цена поменялась вручную) прямое удаление ключа — нормально и просто. Для пакетных пересчётов всего каталога переключение версии на порядок надёжнее и быстрее, чем гонка по удалению тысяч ключей синхронно.
• Считайте hit ratio недостаточной метрикой. Высокий cache hit ratio говорит только о том, что кеш отвечает, а не о том, что ответ свежий. Нужна отдельная метрика staleness: глубина очереди инвалидации и возраст самого старого события в ней — именно она в этом инциденте показала бы проблему за секунды, а не после жалоб из саппорта.
• Пересматривайте пропускную способность фоновых процессов при росте данных. Если очередь заданий, очередь сообщений или воркер были рассчитаны на определённый объём, рост каталога, базы или трафика в 5–10 раз — повод перепроверить, не стал ли вчерашний разумный лимит сегодняшним узким местом. Похожая история с ростом очереди без адаптации лимитов разбиралась в статье про очередь задач, которая росла, пока всё не встало.
• Разделяйте «защита от перегрузки» и «источник инцидента». Мера, добавленная как экстренное лекарство от одной проблемы (перегрузка Redis залповым DEL), сама стала источником другой (устаревшие цены на витрине). При разборе новых защитных мер стоит сразу спрашивать: а что произойдёт с этим ограничением, если нагрузка вырастет в 10 раз? Похожий эффект бывает и в обратную сторону — когда кеш, наоборот, прогревают слишком резко и синхронно; это разобрано в статье про то, как прогрев кеша уронил базу эффектом стада.
• Проверяйте ресурсы самого кешa под реальную нагрузку. Redis в этом случае был не виноват — он простаивал, пока воркер тормозил сам себя. Но если бы дело всё же упёрлось в CPU или диск инстанса, при росте каталога и параллельных воркеров имеет смысл заранее прикинуть запас по ресурсам — как минимум по CPU и памяти, а на выделенном сервере под Redis эта проверка делается заранее, а не в момент инцидента. Базовая установка и настройка описана в статье как установить и настроить Redis на VPS, а если инвалидация и трафик заведомо будут расти дальше — стоит сразу закладываться на настройку кластера Redis, чтобы разносить точки отказа, а не упираться в один инстанс.

Частые вопросы