fix(tradein/scraper): отметки времени прогона перестают замерзать в его же транзакции (#2702) #2718

Merged

bot-backend merged 1 commit from fix/2702-run-timestamps into main

2026-08-06 09:55:51 +00:00

bot-backend commented

2026-08-06 09:40:56 +00:00

Collaborator

Что найдено

now() в PostgreSQL — синоним transaction_timestamp(): замерзает на СТАРТЕ транзакции. Финализаторы прогона выполняются ТОЙ ЖЕ сессией, что и работа задачи, поэтому если её транзакция оставалась открытой всё время работы (коммитить было нечего), их UPDATE попадал ВНУТРЬ неё, и finished_at получал время НАЧАЛА работы.

Прод 2026-08-06 (487 прогонов с finished_at и counters.duration_sec):

153 — заявленная длительность больше окна finished_at − started_at в >1.5 раза;
133 — окно меньше секунды при работе дольше 10 с; 126 из них в диапазоне 9-64 мс — это подпись механизма, а не разброс: столько проходит от коммита claim'а до первого запроса рабочей транзакции.
Прогон 346 (cian_history_backfill): 18 230 с работы, окно 32 мс.

Проверка семантики прямо на проде: SELECT now(), clock_timestamp(), pg_sleep(2), now(), clock_timestamp() → now() не сдвинулся, clock_timestamp() сдвинулся на 2 с.

Почему дефект был не сплошной

Зависел от того, коммитила ли задача перед финалом:

источник	среднее окно	среднее duration_sec
cian_history_backfill	2554	4222	не коммитит перед финалом
newbuilding_enrich	1302	2078	то же
yandex_address_backfill	107	1022	45 из 50 прогонов
avito_detail_backfill	2829	2016	коммитит поштучно
house_imv_backfill	1173	1173	коммитит
cadastral_geo_match	11	10	коммитит

Что сделано

clock_timestamp() вместо now() во всех финализаторах и в heartbeat — обе копии runs-модуля (kit-копия входит в scraper-allowlist деплоя, app-копия нет, но исполняется именно она — расходиться им нельзя).
reap_zombies: обе стороны сравнения — настоящее время (требование п.2). На проде у всех 6 прогонов cian_history_backfill, помеченных zombie, записанный heartbeat остался на отметке старта (max advance 0.0 с) при нормальной длительности до 5.06 ч — критерий решал по замороженной отметке.
Миграция 223: COMMENT на started_at / finished_at / heartbeat_at / counters — история невосстановима, длительность брать из counters->>'duration_sec' (монотонные часы процесса, транзакцией не затронуты).
started_at уже писался своей закоммиченной транзакцией (create_run коммитит INSERT до возврата run_id) — требование п.1 выполнялось и раньше, тест это фиксирует.

Test plan

tests/test_2702_run_timestamps.py — 11 тестов, обе копии модуля; сценарий прогона 346 воспроизведён дословно.
Фальсификация: на старом коде (NOW()) падают 7 из 11.
Полный прогон backend-сьюта: 3653 passed.

Refs #2702

## Что найдено `now()` в PostgreSQL — синоним `transaction_timestamp()`: замерзает на СТАРТЕ транзакции. Финализаторы прогона выполняются ТОЙ ЖЕ сессией, что и работа задачи, поэтому если её транзакция оставалась открытой всё время работы (коммитить было нечего), их UPDATE попадал ВНУТРЬ неё, и `finished_at` получал время НАЧАЛА работы. Прод 2026-08-06 (487 прогонов с `finished_at` и `counters.duration_sec`): - 153 — заявленная длительность больше окна `finished_at − started_at` в >1.5 раза; - 133 — окно меньше секунды при работе дольше 10 с; **126 из них в диапазоне 9-64 мс** — это подпись механизма, а не разброс: столько проходит от коммита claim'а до первого запроса рабочей транзакции. - Прогон 346 (`cian_history_backfill`): 18 230 с работы, окно 32 мс. Проверка семантики прямо на проде: `SELECT now(), clock_timestamp(), pg_sleep(2), now(), clock_timestamp()` → `now()` не сдвинулся, `clock_timestamp()` сдвинулся на 2 с. ## Почему дефект был не сплошной Зависел от того, коммитила ли задача перед финалом: | источник | среднее окно | среднее duration_sec | | |---|---|---|---| | cian_history_backfill | 2554 | 4222 | не коммитит перед финалом | | newbuilding_enrich | 1302 | 2078 | то же | | yandex_address_backfill | 107 | 1022 | 45 из 50 прогонов | | avito_detail_backfill | 2829 | 2016 | коммитит поштучно | | house_imv_backfill | 1173 | 1173 | коммитит | | cadastral_geo_match | 11 | 10 | коммитит | ## Что сделано - `clock_timestamp()` вместо `now()` во всех финализаторах и в heartbeat — **обе** копии runs-модуля (kit-копия входит в scraper-allowlist деплоя, app-копия нет, но исполняется именно она — расходиться им нельзя). - `reap_zombies`: обе стороны сравнения — настоящее время (требование п.2). На проде у всех 6 прогонов `cian_history_backfill`, помеченных `zombie`, записанный heartbeat остался на отметке старта (max advance 0.0 с) при нормальной длительности до 5.06 ч — критерий решал по замороженной отметке. - Миграция 223: COMMENT на `started_at` / `finished_at` / `heartbeat_at` / `counters` — история невосстановима, длительность брать из `counters->>'duration_sec'` (монотонные часы процесса, транзакцией не затронуты). - `started_at` уже писался своей закоммиченной транзакцией (`create_run` коммитит INSERT до возврата `run_id`) — требование п.1 выполнялось и раньше, тест это фиксирует. ## Test plan - [x] `tests/test_2702_run_timestamps.py` — 11 тестов, обе копии модуля; сценарий прогона 346 воспроизведён дословно. - [x] Фальсификация: на старом коде (`NOW()`) падают 7 из 11. - [x] Полный прогон backend-сьюта: 3653 passed. Refs #2702

bot-backend added 1 commit 2026-08-06 09:40:57 +00:00

fix(tradein/scraper): отметки времени прогона перестают замерзать в его же транзакции (#2702 )

CI Trade-In / changes (pull_request) Successful in 9s

Details

CI / changes (pull_request) Successful in 9s

Details

CI Trade-In / frontend-checks (pull_request) Has been skipped

Details

CI / backend-tests (pull_request) Has been skipped

Details

CI / frontend-tests (pull_request) Has been skipped

Details

CI / openapi-codegen-check (pull_request) Has been skipped

Details

CI Trade-In / backend-tests (pull_request) Successful in 3m9s

Details

cfed5ace75

now() в PostgreSQL — синоним transaction_timestamp(): замерзает на СТАРТЕ
транзакции. Финализаторы (mark_done/mark_failed/mark_banned) выполняются той же
сессией, что и работа задачи, поэтому если её транзакция всё это время оставалась
открытой (коммитить было нечего: читающий батч, ноль сохранений, сохранение чужой
сессией), их UPDATE попадал ВНУТРЬ неё и получал время НАЧАЛА работы.

Прод 2026-08-06 (487 прогонов с finished_at и counters.duration_sec): у 153
заявленная длительность больше окна finished_at − started_at в >1.5 раза, у 133
окно меньше секунды при работе дольше 10 с. 126 из этих 133 окон лежат в 9-64 мс —
подпись механизма, а не разброс: столько проходит от коммита claim'а до первого
запроса рабочей транзакции. Прогон 346 (cian_history_backfill): 18 230 с работы,
окно 32 мс.

Дефект не сплошной ровно потому, что зависел от коммита перед финалом:
cadastral_geo_match / house_imv_backfill / avito_detail_backfill коммитят поштучно
(окно = работа), yandex_address_backfill (45 из 50) / newbuilding_enrich /
cian_history_backfill — нет.

Правка: clock_timestamp() вместо now() во всех финализаторах и в heartbeat, обе
копии runs-модуля (kit-копия входит в scraper-allowlist деплоя, app-копия — нет,
но исполняется она; расходиться им нельзя).

Побочно чинится критерий зависших прогонов: reap_zombies сравнивает записанный
heartbeat со «сейчас», и обе стороны обязаны быть настоящим временем. На проде у
всех 6 прогонов cian_history_backfill, помеченных 'zombie', записанный heartbeat
остался на отметке старта (max advance 0.0 с) при нормальной длительности до 5.06 ч.

started_at уже писался своей закоммиченной транзакцией (create_run коммитит INSERT
до возврата run_id) — требование #2702 п.1 выполнялось и раньше; тест это фиксирует.

Историю не переписываем: настоящий finished_at нигде не сохранился, но
counters.duration_sec измерялся монотонными часами процесса и верен. Миграция 223
проставляет это COMMENT'ами на колонках, чтобы аналитика брала длительность из
счётчика, а не из разности отметок.

Refs #2702