lekss361/gendesign

Fork 0

[HIGH] tradein: listing_source_snapshot падает в zombie каждую ночь 6 суток подряд, осиротевшие запросы висят по 46 часов и держат горизонт vacuum #2607

New issue

Closed

opened 2026-07-31 23:12:23 +00:00 by lekss361 · 1 comment

lekss361 commented

2026-07-31 23:12:23 +00:00

Owner

Найдено 2026-08-01 при глубоком ревью миграции #2606 (ревьюер заметил зависшие транзакции при оценке блокировок), диагноз доведён в главной сессии.

Симптом 1 — задача не отрабатывает ни разу

listing_source_snapshot помечается zombie каждую ночь подряд минимум с 26 июля:

 id  |         source          | status |     started (UTC)    |    finished (UTC)
2754 | listing_source_snapshot | zombie | 2026-07-31 01:08:34  | 2026-07-31 07:08:53
2676 | listing_source_snapshot | zombie | 2026-07-30 01:05:12  | 2026-07-30 07:05:30
2595 | listing_source_snapshot | zombie | 2026-07-29 01:02:45  | 2026-07-29 07:03:06
2519 | listing_source_snapshot | zombie | 2026-07-28 01:51:20  | 2026-07-28 07:51:40
2440 | listing_source_snapshot | zombie | 2026-07-27 01:46:49  | 2026-07-27 07:47:12
2357 | listing_source_snapshot | zombie | 2026-07-26 01:14:20  | 2026-07-26 07:14:39

Ровно 6 часов от старта до пометки — это срабатывание zombie-детектора, а не завершение работы. То есть снапшоты цен по источникам не снимаются шесть суток, и никто этого не заметил.

Симптом 2 — осиротевшие запросы живут сутками

Планировщик прогон хоронит и проставляет finished_at, но backend в Postgres продолжает выполнять запрос. На момент разбора висели два, оба в состоянии active (не idle in transaction — реально жгли CPU):

pid	возраст транзакции	соответствует прогону
3693727	1 день 22:06	2676 (старт 2026-07-30 01:05)
3356073	22:03	2754 (старт 2026-07-31 01:08)

Запрос один и тот же:

INSERT INTO listing_source_events ... WITH today AS (
  SELECT listing_source_id, price_rub FROM listing_source_snapshots WHERE s...
)

listing_source_snapshots — 2 596 289 строк. Похоже на отсутствующий или неподходящий индекс: запрос не «завис» на блокировке (wait_event пуст), а честно перебирает данные вторые сутки.

Симптом 3 — горизонт vacuum запинен, таблицы пухнут

Старый backend_xmin этих транзакций не давал очистке переиспользовать мёртвые кортежи:

таблица	живых	мёртвых	%	последний autovacuum
`listings`	249527	40929	14,1%	2026-07-31 23:07 (прошёл, но убрать не смог)
`listing_sources`	83559	16441	16,4%	2026-07-20 — 11 дней назад

Симптом характерный: autovacuum по listings отработал, а процент мёртвых не упал — горизонт держали эти транзакции.

Симптом 4 — на проде нет ни одного предохранителя

statement_timeout                   = 0
lock_timeout                        = 0
idle_in_transaction_session_timeout = 0

Поэтому запрос и может выполняться 46 часов: остановить его некому.

Сделано сейчас

Оба осиротевших backend'а сняты pg_terminate_backend — их результата никто не ждал (прогоны уже закрыты как zombie). Проверено: транзакций старше 30 минут не осталось. Мёртвые кортежи пока на месте (40929 / 16441) — их подберёт ближайший autovacuum, теперь горизонт свободен.

Это разовое лечение симптома. Причина не устранена.

Что делать

Починить сам запрос — разобрать план INSERT INTO listing_source_events ... FROM listing_source_snapshots на 2,6 млн строк, добавить индекс или переписать. Сейчас задача не выполняется в принципе.
Ставить предохранители: statement_timeout для скрапер-роли (задача с бюджетом в часах не должна иметь право висеть сутки) и idle_in_transaction_session_timeout на уровне БД.
Zombie-детектор должен убивать backend, а не только помечать строку. Сейчас он закрывает scrape_runs, создавая ложное впечатление, что прогон завершён, тогда как запрос продолжает работать и вредить. Расхождение между состоянием приложения и состоянием БД — корень симптомов 2 и 3.
Мониторинг: 6 ночей подряд zombie по одному источнику — это должно было поднять алерт. В scrape_runs.py есть механизм алерта на N подряд failed/banned, но zombie в него, судя по всему, не входит. Проверить и добавить.

Связано: #2604 (соседний случай молчаливой неработающей ночной задачи — геокодирование давало saved=0 восемь ночей подряд и тоже не алертило).

Найдено 2026-08-01 при глубоком ревью миграции #2606 (ревьюер заметил зависшие транзакции при оценке блокировок), диагноз доведён в главной сессии. ## Симптом 1 — задача не отрабатывает ни разу `listing_source_snapshot` помечается `zombie` **каждую ночь подряд** минимум с 26 июля: ``` id | source | status | started (UTC) | finished (UTC) 2754 | listing_source_snapshot | zombie | 2026-07-31 01:08:34 | 2026-07-31 07:08:53 2676 | listing_source_snapshot | zombie | 2026-07-30 01:05:12 | 2026-07-30 07:05:30 2595 | listing_source_snapshot | zombie | 2026-07-29 01:02:45 | 2026-07-29 07:03:06 2519 | listing_source_snapshot | zombie | 2026-07-28 01:51:20 | 2026-07-28 07:51:40 2440 | listing_source_snapshot | zombie | 2026-07-27 01:46:49 | 2026-07-27 07:47:12 2357 | listing_source_snapshot | zombie | 2026-07-26 01:14:20 | 2026-07-26 07:14:39 ``` Ровно 6 часов от старта до пометки — это срабатывание zombie-детектора, а не завершение работы. То есть снапшоты цен по источникам **не снимаются шесть суток**, и никто этого не заметил. ## Симптом 2 — осиротевшие запросы живут сутками Планировщик прогон хоронит и проставляет `finished_at`, но backend в Postgres продолжает выполнять запрос. На момент разбора висели два, оба в состоянии `active` (не `idle in transaction` — реально жгли CPU): | pid | возраст транзакции | соответствует прогону | |---|---|---| | 3693727 | **1 день 22:06** | 2676 (старт 2026-07-30 01:05) | | 3356073 | **22:03** | 2754 (старт 2026-07-31 01:08) | Запрос один и тот же: ```sql INSERT INTO listing_source_events ... WITH today AS ( SELECT listing_source_id, price_rub FROM listing_source_snapshots WHERE s... ) ``` `listing_source_snapshots` — **2 596 289 строк**. Похоже на отсутствующий или неподходящий индекс: запрос не «завис» на блокировке (`wait_event` пуст), а честно перебирает данные вторые сутки. ## Симптом 3 — горизонт vacuum запинен, таблицы пухнут Старый `backend_xmin` этих транзакций не давал очистке переиспользовать мёртвые кортежи: | таблица | живых | мёртвых | % | последний autovacuum | |---|---|---|---|---| | `listings` | 249527 | **40929** | 14,1% | 2026-07-31 23:07 (прошёл, но убрать не смог) | | `listing_sources` | 83559 | **16441** | 16,4% | **2026-07-20** — 11 дней назад | Симптом характерный: autovacuum по `listings` отработал, а процент мёртвых не упал — горизонт держали эти транзакции. ## Симптом 4 — на проде нет ни одного предохранителя ``` statement_timeout = 0 lock_timeout = 0 idle_in_transaction_session_timeout = 0 ``` Поэтому запрос и может выполняться 46 часов: остановить его некому. ## Сделано сейчас Оба осиротевших backend'а сняты `pg_terminate_backend` — их результата никто не ждал (прогоны уже закрыты как zombie). Проверено: транзакций старше 30 минут не осталось. Мёртвые кортежи пока на месте (40929 / 16441) — их подберёт ближайший autovacuum, теперь горизонт свободен. Это разовое лечение симптома. Причина не устранена. ## Что делать 1. **Починить сам запрос** — разобрать план `INSERT INTO listing_source_events ... FROM listing_source_snapshots` на 2,6 млн строк, добавить индекс или переписать. Сейчас задача не выполняется в принципе. 2. **Ставить предохранители**: `statement_timeout` для скрапер-роли (задача с бюджетом в часах не должна иметь право висеть сутки) и `idle_in_transaction_session_timeout` на уровне БД. 3. **Zombie-детектор должен убивать backend, а не только помечать строку.** Сейчас он закрывает `scrape_runs`, создавая ложное впечатление, что прогон завершён, тогда как запрос продолжает работать и вредить. Расхождение между состоянием приложения и состоянием БД — корень симптомов 2 и 3. 4. **Мониторинг**: 6 ночей подряд zombie по одному источнику — это должно было поднять алерт. В `scrape_runs.py` есть механизм алерта на N подряд `failed`/`banned`, но `zombie` в него, судя по всему, не входит. Проверить и добавить. Связано: #2604 (соседний случай молчаливой неработающей ночной задачи — геокодирование давало `saved=0` восемь ночей подряд и тоже не алертило).

lekss361 referenced this issue

2026-08-01 18:30:42 +00:00

[CRITICAL] tradein: скрапер не пишет город в адрес объявления — данные области уходят в Екатеринбург #2594

lekss361 referenced this issue

2026-08-01 19:15:36 +00:00

[HIGH] tradein: ночное геокодирование даёт 0 сохранённых 8 прогонов подряд — очередь на 98% забита неактивными объявлениями чужих регионов #2604

bot-backend referenced this issue from a commit

2026-08-02 08:55:53 +00:00

fix(tradein/snapshot): починить зависающий запрос снапшотов и добавить бюджет времени (#2607)

lekss361 referenced this issue

2026-08-02 08:57:37 +00:00

fix(tradein/snapshot): починить зависающий запрос снапшотов и бюджет времени (#2607) #2618

lekss361 referenced this issue from a commit

2026-08-02 09:19:22 +00:00

Merge pull request 'fix(tradein/snapshot): починить зависающий запрос снапшотов и бюджет времени (#2607)' (#2618) from fix/tradein-snapshot-query-perf into main

lekss361 commented

2026-08-02 09:28:22 +00:00

Author

Owner

✅ Закрываю — задача отработала впервые с 26 июля, проверено запуском на проде.

PR #2618 в проде (f488cbcf). Прогон вне расписания сразу после деплоя:

id   | status | сек | counters
2969 | done   |  6  | {"snapshotted": 85085, "price_change_events": 620}

Шесть секунд против прогонов, не завершавшихся за шесть часов и оставлявших запросы в базе на 46 часов.

проверка	до	после
`listing_source_snapshots` max date	2026-07-29	2026-08-02
строк в таблице	2 784 049	2 869 134 (+85 085)
`listing_source_events`	6 622	7 242 (+620)
зависших транзакций	2 (46 ч и 22 ч)	0

Причина — ловушка планировщика, а не медленный запрос

prior-CTE делала DISTINCT ON (listing_source_id) ... WHERE snapshot_date < CURRENT_DATE по всей таблице (2,78 млн строк, 81 387 различных источников) и джойнилась с today обычным JOIN.

Ключевое: планировщик оценивает snapshot_date = CURRENT_DATE в одну строку — строки вставлены в той же транзакции, ANALYZE их не видел, а CURRENT_DATE всегда за правым краем гистограммы. На этом основании выбирается Nested Loop без Materialize, и каждая из ~85 тысяч реальных строк today заново считает DISTINCT ON по всей таблице. Стоимость внутренней части ≈298 627 на строку.

Nested Loop (cost=0.86..299785.55 rows=1)
  -> Index Scan (snapshot_date = CURRENT_DATE), rows=1     ← оценка, реально 85 085
  -> Subquery Scan on p (cost=0.43..298627.09 rows=76927)
       -> Unique -> Index Scan (snapshot_date < ...) rows=2670104

Лечение: JOIN LATERAL (... ORDER BY snapshot_date DESC LIMIT 1) ON true — точечный поиск по существующему индексу idx_lss_source_date (listing_source_id, snapshot_date DESC), порядок колонок под этот паттерн идеален. Стоимость внутренней части упала с 298 627 до ~4,4.

Проверки при ревью, которые стоит отметить

Эквивалентность доказана структурно, а не «выглядит так же». Тай-брейк при двух снимках одного источника за одну дату физически невозможен: PRIMARY KEY (listing_source_id, snapshot_date). Поведение при отсутствии предыдущего снимка идентично — JOIN LATERAL ... ON true без LEFT сохраняет INNER-семантику старого JOIN.

Быстродействие подтверждено настоящим замером. Старый запрос замерить нельзя — он вешает базу; новый обязан быть быстрым, поэтому ревьюер прогнал EXPLAIN ANALYZE над SELECT-версией на реальных данных: 454 мс на 81 387 строках. Фактический прогон дал 6 с (с учётом самой вставки снимков).

Тесты проверены мутацией: возврат к DISTINCT ON → тест краснеет; подмена клампа бюджета → краснеет; удаление SET LOCAL statement_timeout → краснеют два.

Защита от инъекции в бюджете реальная: budget_sec проходит через кламп [30, 3600], эмпирически прогнаны NaN, ±inf, bool, list, "1e400" — на выходе всегда int.

Что из issue сделано, а что нет

✅ п.1 запрос — переписан, 6 секунд.
✅ предохранитель — budget_sec → SET LOCAL statement_timeout (per-transaction, не серверный), дефолт 900 с, миграция 202 задаёт его в расписании. При срабатывании прогон честно уходит в failed с причиной, а не висит.
⬜ п.2 серверные таймауты (statement_timeout/idle_in_transaction_session_timeout на уровне роли) — НЕ делалось намеренно: может сломать легитимные долгие задачи, требует отдельного решения.
⬜ п.3 зомби-детектор убивает backend — отложено осознанно. В scrape_runs нет pid/application_name, добавление требует схемного изменения и pid-reuse-safe дизайна. Дыры это не оставляет: statement_timeout — самоотмена изнутри backend'а (включая ожидание на локах), а верхняя граница бюджета 3600 с жёстко проверяется в Python независимо от значения в БД. Максимум зависания — час против шестичасового порога детектора.
⬜ п.4 zombie в алертах — не делалось. Остаётся справедливым: шесть ночей подряд зомби по одному источнику не подняли ни одного оповещения, потому что механизм алерта учитывает только failed/banned. Стоит отдельной задачи.

Разовый всплеск событий, предсказанный при ревью, материализовался скромно: 620 событий за четыре пропущенных дня — это кумулятивное изменение цены, атрибутированное одним днём. Промежуточные движения за 30 июля — 1 августа физически потеряны из-за самого простоя, а не из-за переписывания запроса.

✅ **Закрываю — задача отработала впервые с 26 июля, проверено запуском на проде.** PR #2618 в проде (`f488cbcf`). Прогон вне расписания сразу после деплоя: ``` id | status | сек | counters 2969 | done | 6 | {"snapshotted": 85085, "price_change_events": 620} ``` **Шесть секунд** против прогонов, не завершавшихся за шесть часов и оставлявших запросы в базе на 46 часов. | проверка | до | после | |---|---|---| | `listing_source_snapshots` max date | 2026-07-29 | **2026-08-02** | | строк в таблице | 2 784 049 | **2 869 134** (+85 085) | | `listing_source_events` | 6 622 | **7 242** (+620) | | зависших транзакций | 2 (46 ч и 22 ч) | **0** | ## Причина — ловушка планировщика, а не медленный запрос `prior`-CTE делала `DISTINCT ON (listing_source_id) ... WHERE snapshot_date < CURRENT_DATE` по всей таблице (2,78 млн строк, 81 387 различных источников) и джойнилась с `today` обычным JOIN. Ключевое: планировщик оценивает `snapshot_date = CURRENT_DATE` в **одну строку** — строки вставлены в той же транзакции, ANALYZE их не видел, а `CURRENT_DATE` всегда за правым краем гистограммы. На этом основании выбирается `Nested Loop` **без `Materialize`**, и каждая из ~85 тысяч реальных строк `today` заново считает `DISTINCT ON` по всей таблице. Стоимость внутренней части ≈298 627 на строку. ``` Nested Loop (cost=0.86..299785.55 rows=1) -> Index Scan (snapshot_date = CURRENT_DATE), rows=1 ← оценка, реально 85 085 -> Subquery Scan on p (cost=0.43..298627.09 rows=76927) -> Unique -> Index Scan (snapshot_date < ...) rows=2670104 ``` Лечение: `JOIN LATERAL (... ORDER BY snapshot_date DESC LIMIT 1) ON true` — точечный поиск по существующему индексу `idx_lss_source_date (listing_source_id, snapshot_date DESC)`, порядок колонок под этот паттерн идеален. Стоимость внутренней части упала с 298 627 до ~4,4. ## Проверки при ревью, которые стоит отметить **Эквивалентность доказана структурно, а не «выглядит так же».** Тай-брейк при двух снимках одного источника за одну дату физически невозможен: `PRIMARY KEY (listing_source_id, snapshot_date)`. Поведение при отсутствии предыдущего снимка идентично — `JOIN LATERAL ... ON true` без `LEFT` сохраняет INNER-семантику старого JOIN. **Быстродействие подтверждено настоящим замером.** Старый запрос замерить нельзя — он вешает базу; новый обязан быть быстрым, поэтому ревьюер прогнал `EXPLAIN ANALYZE` над `SELECT`-версией на реальных данных: **454 мс на 81 387 строках**. Фактический прогон дал 6 с (с учётом самой вставки снимков). **Тесты проверены мутацией**: возврат к `DISTINCT ON` → тест краснеет; подмена клампа бюджета → краснеет; удаление `SET LOCAL statement_timeout` → краснеют два. **Защита от инъекции в бюджете реальная**: `budget_sec` проходит через кламп `[30, 3600]`, эмпирически прогнаны `NaN`, `±inf`, `bool`, `list`, `"1e400"` — на выходе всегда int. ## Что из issue сделано, а что нет - ✅ **п.1 запрос** — переписан, 6 секунд. - ✅ **предохранитель** — `budget_sec` → `SET LOCAL statement_timeout` (per-transaction, не серверный), дефолт 900 с, миграция 202 задаёт его в расписании. При срабатывании прогон честно уходит в `failed` с причиной, а не висит. - ⬜ **п.2 серверные таймауты** (`statement_timeout`/`idle_in_transaction_session_timeout` на уровне роли) — НЕ делалось намеренно: может сломать легитимные долгие задачи, требует отдельного решения. - ⬜ **п.3 зомби-детектор убивает backend** — отложено осознанно. В `scrape_runs` нет `pid`/`application_name`, добавление требует схемного изменения и pid-reuse-safe дизайна. Дыры это не оставляет: `statement_timeout` — самоотмена изнутри backend'а (включая ожидание на локах), а верхняя граница бюджета 3600 с жёстко проверяется в Python независимо от значения в БД. Максимум зависания — час против шестичасового порога детектора. - ⬜ **п.4 zombie в алертах** — не делалось. Остаётся справедливым: шесть ночей подряд зомби по одному источнику не подняли ни одного оповещения, потому что механизм алерта учитывает только `failed`/`banned`. Стоит отдельной задачи. Разовый всплеск событий, предсказанный при ревью, материализовался скромно: 620 событий за четыре пропущенных дня — это кумулятивное изменение цены, атрибутированное одним днём. Промежуточные движения за 30 июля — 1 августа физически потеряны из-за самого простоя, а не из-за переписывания запроса.

lekss361 closed this issue

2026-08-02 09:28:26 +00:00

lekss361 referenced this issue

2026-08-02 11:24:00 +00:00

[HIGH] tradein/scraper: капча Циана и пустые выдачи Яндекса засчитываются как успешный прогон — 41 из 68 прогонов за 2 недели забрали ноль лотов без ед… #2625