lekss361/gendesign

Fork 0

tradein: отметки времени прогона не охватывают его работу — 153 прогона из 487 «длятся» дольше собственного окна, пятичасовой записан как 32 мс #2702

New issue

Closed

opened 2026-08-06 06:21:55 +00:00 by bot-backend · 1 comment

bot-backend commented

2026-08-06 06:21:55 +00:00

Collaborator

Найдено при разборе detail-backfill'ов (эпик #2674, PR #2695). Отметки времени прогона не охватывают работу, которую он делал.

Замер

487 прогонов, у которых есть и finished_at, и счётчик duration_sec:

	Прогонов
`duration_sec` больше окна `finished_at − started_at` более чем в 1.5 раза	153
то же, более чем в 10 раз	12
окно меньше секунды при заявленных больше 10 секунд работы	133

Заявленная длительность, превышающая собственное окно, невозможна: работа не может занять больше времени, чем прошло между началом и концом.

Крайние случаи:

id   source                  окно, с   duration_sec
346  cian_history_backfill      0.032         18 230
497  newbuilding_enrich         0.021          6 124
339  newbuilding_enrich         0.101          6 021
2037 newbuilding_enrich         0.019          2 316
341  yandex_address_backfill    0.019          1 460

Прогон id 346 работал пять часов и записан как длившийся 32 миллисекунды.

Что это значит

Окно шириной в десятки миллисекунд при часах работы означает, что started_at и finished_at проставляются практически одновременно — в конце, а не в начале. Строка прогона либо создаётся при финализации, либо started_at перезаписывается в транзакции, открытой уже после старта работы.

По источникам видно, что дефект не сплошной:

source                    среднее окно   среднее reported
cian_history_backfill           2 554.1           4 222.3   ← окно короче работы
newbuilding_enrich              1 301.7           2 077.5   ← короче
yandex_address_backfill           106.6           1 022.3   ← короче в 10 раз
avito_detail_backfill           2 828.5           2 016.1   ← длиннее (нормально)
house_imv_backfill              1 173.0           1 172.5   ← совпадает
cadastral_geo_match                10.8              10.3   ← совпадает

Часть задач пишет время корректно. Значит это не общий механизм, а конкретные пути финализации — и их надо найти поимённо, а не чинить «в целом».

Чем это мешает

duration_sec внутри JSON-счётчиков — сейчас единственное правдивое число о длительности. Всё, что считает по колонкам:

«сколько занимает сбор», «ускорился ли источник», любое сравнение тактов — неверно;
окно прогона используется для поиска зависших прогонов (zombie) — на строке с 32-миллисекундным окном этот критерий смысла не имеет;
монитор свежести и админские витрины опираются на started_at/finished_at.

Ошибка при этом тихая: запрос возвращает числа, они правдоподобны, проверить их без сверки со вторым источником нельзя. Это тот же класс, что и остальные находки эпика.

Что нужно

Найти поимённо пути финализации, где started_at проставляется в конце (сравнить с теми, где совпадает — house_imv_backfill, cadastral_geo_match).
Проставлять started_at в момент старта, отдельной зафиксированной транзакцией, чтобы её не откатывало вместе с рабочей.
Проверить, не сломан ли тем же самым критерий поиска зависших прогонов.
Исторические 153 строки не восстановимы по окну — но duration_sec у них есть, и это стоит записать, чтобы аналитика бралась из него, а не из разности.

Связано: #2674, #2695, #2691, #2670.

Найдено при разборе detail-backfill'ов (эпик #2674, PR #2695). Отметки времени прогона **не охватывают работу, которую он делал**. ## Замер 487 прогонов, у которых есть и `finished_at`, и счётчик `duration_sec`: | | Прогонов | |---|---:| | `duration_sec` больше окна `finished_at − started_at` **более чем в 1.5 раза** | **153** | | то же, **более чем в 10 раз** | 12 | | окно **меньше секунды** при заявленных **больше 10 секунд** работы | **133** | Заявленная длительность, превышающая собственное окно, невозможна: работа не может занять больше времени, чем прошло между началом и концом. Крайние случаи: ``` id source окно, с duration_sec 346 cian_history_backfill 0.032 18 230 497 newbuilding_enrich 0.021 6 124 339 newbuilding_enrich 0.101 6 021 2037 newbuilding_enrich 0.019 2 316 341 yandex_address_backfill 0.019 1 460 ``` Прогон **id 346** работал пять часов и записан как длившийся **32 миллисекунды**. ## Что это значит Окно шириной в десятки миллисекунд при часах работы означает, что `started_at` и `finished_at` проставляются практически одновременно — **в конце**, а не в начале. Строка прогона либо создаётся при финализации, либо `started_at` перезаписывается в транзакции, открытой уже после старта работы. По источникам видно, что дефект не сплошной: ``` source среднее окно среднее reported cian_history_backfill 2 554.1 4 222.3 ← окно короче работы newbuilding_enrich 1 301.7 2 077.5 ← короче yandex_address_backfill 106.6 1 022.3 ← короче в 10 раз avito_detail_backfill 2 828.5 2 016.1 ← длиннее (нормально) house_imv_backfill 1 173.0 1 172.5 ← совпадает cadastral_geo_match 10.8 10.3 ← совпадает ``` Часть задач пишет время корректно. Значит это не общий механизм, а конкретные пути финализации — и их надо найти поимённо, а не чинить «в целом». ## Чем это мешает `duration_sec` внутри JSON-счётчиков — сейчас **единственное правдивое** число о длительности. Всё, что считает по колонкам: - «сколько занимает сбор», «ускорился ли источник», любое сравнение тактов — неверно; - окно прогона используется для поиска зависших прогонов (`zombie`) — на строке с 32-миллисекундным окном этот критерий смысла не имеет; - монитор свежести и админские витрины опираются на `started_at`/`finished_at`. Ошибка при этом **тихая**: запрос возвращает числа, они правдоподобны, проверить их без сверки со вторым источником нельзя. Это тот же класс, что и остальные находки эпика. ## Что нужно 1. Найти поимённо пути финализации, где `started_at` проставляется в конце (сравнить с теми, где совпадает — `house_imv_backfill`, `cadastral_geo_match`). 2. Проставлять `started_at` в момент старта, отдельной зафиксированной транзакцией, чтобы её не откатывало вместе с рабочей. 3. Проверить, не сломан ли тем же самым критерий поиска зависших прогонов. 4. Исторические 153 строки не восстановимы по окну — но `duration_sec` у них есть, и это стоит записать, чтобы аналитика бралась из него, а не из разности. Связано: #2674, #2695, #2691, #2670.

bot-backend referenced this issue

2026-08-06 06:30:37 +00:00

[EPIC] МЕРА: 47 мест, где код написан, отревьюен, смержен — и ни разу не сработал на проде #2674

Light1YT referenced this issue from a commit

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

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

bot-backend referenced this issue

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

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

bot-backend referenced this issue from a commit

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

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

Light1YT referenced this issue from a commit

2026-08-06 09:58:39 +00:00

merge main (#2702 clock_timestamp) в ветку #2670

bot-backend referenced this issue

2026-08-06 11:09:07 +00:00

fix(tradein/scraper): сигнал живости cian_history_backfill шлётся один раз — живые прогоны reap'ятся как zombie #2725

bot-backend referenced this issue

2026-08-06 12:15:47 +00:00

tradein: «время наблюдения» у снимка — это время начала транзакции сбора; 219 строк семиминутного прогона несут одну метку #2731

bot-backend commented

2026-08-07 09:13:18 +00:00

Author

Collaborator

ЗАКРЫВАЮ: после правки 0 нарушений, два самых сломанных источника переехали корректно

Историческая база (пересчитал сам, тем же выражением):

496 прогонов с finished_at и counters.duration_sec
  153 — duration_sec больше окна более чем в 1.5 раза
  145 — более чем в 10 раз
  133 — окно меньше секунды при работе дольше 10 с

Ваши 153 и 133 воспроизвелись точно.

После правки (прогоны, стартовавшие позже 2026-08-06 10:00 UTC):

8 прогонов с обоими числами
0 — с duration_sec больше окна в 1.5 раза
0 — с окном меньше секунды

Решающее — именно те источники, что были сломаны. Не «в среднем стало лучше», а
поимённо те, у кого дефект и жил:

источник                  окно, с   duration_sec   когда
newbuilding_enrich          440.4        440        07.08 00:39  ← ПОСЛЕ
newbuilding_enrich            0.036      435        06.08 00:05  ← ДО
yandex_detail_backfill     1 812.0      1 811.5     07.08 01:55  ← ПОСЛЕ (было 31 нарушение)
avito_detail_backfill        128.4        128       07.08 07:55
domclick_detail_backfill     168.7        168       06.08 15:17

newbuilding_enrich — 24 нарушения в истории, окна по 20-40 мс при работе в часы; теперь
окно совпадает с работой до десятых секунды.

Все четыре пункта задачи закрыты, причём п.1 — корнем, а не поимённо. Правка заменила
now() на clock_timestamp() во всех финализаторах и в heartbeat, в обеих копиях
(app/services/scrape_runs.py + packages/scraper-kit/.../orchestration/runs.py), то есть
искать пути «поимённо» не пришлось — они все ходят через одни и те же функции.

п.3 (не сломан ли тем же критерий поиска зависших) — закрыт тем же: heartbeat_at писался
тем же now() и отставал на возраст открытой транзакции; на нём стоит reap_zombies.
п.4 (историю брать из duration_sec) — миграция 223 применена на проде,
COMMENT ON COLUMN стоят на started_at, finished_at, heartbeat_at и counters;
комментарий к finished_at прямо предупреждает, что у строк до 06.08 значение недостоверно.

Что осталось непроверенным и почему это не блокер: два источника с историческими
нарушениями после правки ещё не бегали — yandex_address_backfill (45 нарушений, последний
прогон 03.08) и yandex_newbuilding_sweep (20, 03.08). Они ходят через те же самые
финализаторы, что и четыре подтверждённых, отдельного пути финализации у них нет.

Критерий выполнен числом. Закрываю.

## ЗАКРЫВАЮ: после правки 0 нарушений, два самых сломанных источника переехали корректно **Историческая база (пересчитал сам, тем же выражением):** ``` 496 прогонов с finished_at и counters.duration_sec 153 — duration_sec больше окна более чем в 1.5 раза 145 — более чем в 10 раз 133 — окно меньше секунды при работе дольше 10 с ``` Ваши 153 и 133 воспроизвелись точно. **После правки (прогоны, стартовавшие позже 2026-08-06 10:00 UTC):** ``` 8 прогонов с обоими числами 0 — с duration_sec больше окна в 1.5 раза 0 — с окном меньше секунды ``` **Решающее — именно те источники, что были сломаны.** Не «в среднем стало лучше», а поимённо те, у кого дефект и жил: ``` источник окно, с duration_sec когда newbuilding_enrich 440.4 440 07.08 00:39 ← ПОСЛЕ newbuilding_enrich 0.036 435 06.08 00:05 ← ДО yandex_detail_backfill 1 812.0 1 811.5 07.08 01:55 ← ПОСЛЕ (было 31 нарушение) avito_detail_backfill 128.4 128 07.08 07:55 domclick_detail_backfill 168.7 168 06.08 15:17 ``` `newbuilding_enrich` — 24 нарушения в истории, окна по 20-40 мс при работе в часы; теперь окно совпадает с работой до десятых секунды. **Все четыре пункта задачи закрыты, причём п.1 — корнем, а не поимённо.** Правка заменила `now()` на `clock_timestamp()` во **всех** финализаторах и в heartbeat, в обеих копиях (`app/services/scrape_runs.py` + `packages/scraper-kit/.../orchestration/runs.py`), то есть искать пути «поимённо» не пришлось — они все ходят через одни и те же функции. - **п.3** (не сломан ли тем же критерий поиска зависших) — закрыт тем же: `heartbeat_at` писался тем же `now()` и отставал на возраст открытой транзакции; на нём стоит `reap_zombies`. - **п.4** (историю брать из `duration_sec`) — миграция **223 применена на проде**, `COMMENT ON COLUMN` стоят на `started_at`, `finished_at`, `heartbeat_at` и `counters`; комментарий к `finished_at` прямо предупреждает, что у строк до 06.08 значение недостоверно. **Что осталось непроверенным и почему это не блокер:** два источника с историческими нарушениями после правки ещё не бегали — `yandex_address_backfill` (45 нарушений, последний прогон 03.08) и `yandex_newbuilding_sweep` (20, 03.08). Они ходят через те же самые финализаторы, что и четыре подтверждённых, отдельного пути финализации у них нет. Критерий выполнен числом. Закрываю.

bot-backend closed this issue

2026-08-07 09:13:22 +00:00

bot-backend referenced this issue

2026-08-24 16:14:39 +00:00

Телеметрия: метрики и Grafana — сегодня тихий отказ не виден ничем #3078

bot-backend referenced this issue

2026-08-27 08:59:40 +00:00

Планировщик: зомби после ребута хоста блокируют источники до 6 часов — нужен boot-reap по границе старта контейнера #3122

Light1YT referenced this issue from a commit

2026-08-27 09:17:47 +00:00

feat(tradein/scheduler): boot-reap — прогоны предыдущего контейнера снимаются на старте (#3122)

bot-backend referenced this issue