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

Closed
opened 2026-08-06 12:15:47 +00:00 by bot-backend · 4 comments
Collaborator

Найдено попутно при удалении position_in_serp (#2697). Тот же корень, что #2702, но на данных, а не на служебных колонках прогона — и потому опаснее.

Замер

Дневные снимки за сегодня, по прогонам:

run_id   строк   различных меток observed_at   min = max
3293      297             1                   09:40:39.337
3299      235             1                   10:58:49.542
3303      219             1                   11:59:59.675
3287      150             1                   08:10:48.687
3283      148             1                   07:40:47.452
3258      137             1                   02:49:44.831

У каждого прогона все строки несут одну и ту же метку времени наблюдения. Прогон 3303 шёл с 11:59:59 до 12:07:19 — семь с лишним минут, — и все 219 его снимков помечены нулевой секундой.

Почему так

upsert_listing_snapshot пишет observed_at = NOW(), а NOW() в Postgres — это transaction_timestamp(), время начала транзакции, а не текущий момент. Ровно тот механизм, который PR #2718 сегодня починил для finished_at/heartbeat_at прогонов.

Разница в том, что там речь шла о служебном учёте, а здесь — о колонке с содержательным именем, которую читает аналитика.

Что это ломает

observed_at обещает «когда объявление было увидено», а несёт «когда началась транзакция сбора». Всё, что опирается на порядок или тайминг внутри прогона, неверно:

  • нельзя сказать, что было собрано раньше в пределах одного обхода;
  • нельзя восстановить темп сбора по данным;
  • при слиянии двух прогонов за сутки метка достаётся последнему писателю целиком, а не по строкам — этим уже объяснялась невозможность бэкфилла run_id (#2701).

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

Что предлагается

Заменить NOW() на clock_timestamp() в писателе снимков — так же, как сделано в #2718 для колонок прогона.

Оговорка, которую надо решить явно: это меняет смысл уже накопленных данных относительно новых. Исторические строки останутся схлопнутыми и невосстановимы (внутрипрогонное время нигде больше не сохранялось). Значит либо в комментарии к колонке фиксируется дата перехода, либо аналитика по observed_at до этой даты считается неприменимой. Второе честнее.

Отдельно стоит проверить остальные писатели на тот же NOW() в содержательных колонках времени — scraped_at, last_seen_at, fetched_at, detail_enriched_at. Если они схлопываются так же, то фильтры свежести (14 суток) работают по времени начала транзакции, и для долгих прогонов это смещение в несколько часов. Этот замер я не делал.

Связано: #2702, #2718, #2701, #2697.

Найдено попутно при удалении `position_in_serp` (#2697). Тот же корень, что #2702, но на **данных**, а не на служебных колонках прогона — и потому опаснее. ## Замер Дневные снимки за сегодня, по прогонам: ``` run_id строк различных меток observed_at min = max 3293 297 1 09:40:39.337 3299 235 1 10:58:49.542 3303 219 1 11:59:59.675 3287 150 1 08:10:48.687 3283 148 1 07:40:47.452 3258 137 1 02:49:44.831 ``` **У каждого прогона все строки несут одну и ту же метку времени наблюдения.** Прогон 3303 шёл с 11:59:59 до 12:07:19 — семь с лишним минут, — и все 219 его снимков помечены нулевой секундой. ## Почему так `upsert_listing_snapshot` пишет `observed_at = NOW()`, а `NOW()` в Postgres — это `transaction_timestamp()`, время **начала транзакции**, а не текущий момент. Ровно тот механизм, который PR #2718 сегодня починил для `finished_at`/`heartbeat_at` прогонов. Разница в том, что там речь шла о служебном учёте, а здесь — о колонке с содержательным именем, которую читает аналитика. ## Что это ломает `observed_at` обещает «когда объявление было увидено», а несёт «когда началась транзакция сбора». Всё, что опирается на порядок или тайминг **внутри** прогона, неверно: - нельзя сказать, что было собрано раньше в пределах одного обхода; - нельзя восстановить темп сбора по данным; - при слиянии двух прогонов за сутки метка достаётся последнему писателю целиком, а не по строкам — этим уже объяснялась невозможность бэкфилла `run_id` (#2701). Ошибка при этом **тихая**: значения правдоподобны, разброс внутри суток есть, и заметить схлопывание можно только сравнив число строк с числом различных меток. ## Что предлагается Заменить `NOW()` на `clock_timestamp()` в писателе снимков — так же, как сделано в #2718 для колонок прогона. Оговорка, которую надо решить явно: это **меняет смысл** уже накопленных данных относительно новых. Исторические строки останутся схлопнутыми и невосстановимы (внутрипрогонное время нигде больше не сохранялось). Значит либо в комментарии к колонке фиксируется дата перехода, либо аналитика по `observed_at` до этой даты считается неприменимой. Второе честнее. Отдельно стоит проверить остальные писатели на тот же `NOW()` в **содержательных** колонках времени — `scraped_at`, `last_seen_at`, `fetched_at`, `detail_enriched_at`. Если они схлопываются так же, то фильтры свежести (14 суток) работают по времени начала транзакции, и для долгих прогонов это смещение в несколько часов. Этот замер я не делал. Связано: #2702, #2718, #2701, #2697.
Author
Collaborator

Замер, который я обещал: да, схлопываются все три — но соразмерность важна

scraped_at по часам за сегодня:

час     строк   различных меток
11:00     219          1
10:00     235          1
09:00     297          1
08:00     150          1
07:00     148          1
06:00     130          1
04:00     496          1
03:00     137          1

last_seen_at за сегодня: 2 130 строк, 10 различных меток — ровно по одной на прогон.

То есть механизм универсален: все содержательные колонки времени в писателях объявлений несут время начала транзакции сбора, а не момент наблюдения строки.

Но вывод про фильтры свежести я делаю обратный тому, на который намекал

Смещение равно длительности прогона. Типичный прогон — минуты (3303 шёл 7 минут), самый длинный на проде — 17.3 часа (cian_full_load). Против окна свежести в 14 суток это от 0.03% до 5% в худшем случае.

Практического искажения фильтров свежести и TTL нет. Моя формулировка в теле задачи («для долгих прогонов это смещение в часы») верна буквально, но подразумевала значимость, которой здесь нет. Снимаю это как основание для срочности.

Где цена настоящая

Аналитическая, а не фильтрующая:

  • темп сбора по данным не восстановить — все строки прогона выглядят одномоментными;
  • порядок внутри прогона не восстановить — отсюда же следовала невозможность бэкфилла run_id (#2701);
  • любое рассуждение вида «сначала увидели А, потом Б» в пределах прогона неверно, а выглядит правдоподобно.

Плюс частный эффект: scraped_at и last_seen_at согласованы между собой именно потому, что оба врут одинаково. Если чинить, чинить надо оба сразу, иначе появится расхождение там, где его сейчас нет.

Приоритет

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

## Замер, который я обещал: да, схлопываются все три — но соразмерность важна `scraped_at` по часам за сегодня: ``` час строк различных меток 11:00 219 1 10:00 235 1 09:00 297 1 08:00 150 1 07:00 148 1 06:00 130 1 04:00 496 1 03:00 137 1 ``` `last_seen_at` за сегодня: **2 130 строк, 10 различных меток** — ровно по одной на прогон. То есть механизм универсален: все содержательные колонки времени в писателях объявлений несут время начала транзакции сбора, а не момент наблюдения строки. ## Но вывод про фильтры свежести я делаю обратный тому, на который намекал Смещение равно длительности прогона. Типичный прогон — минуты (3303 шёл 7 минут), самый длинный на проде — 17.3 часа (`cian_full_load`). Против окна свежести в **14 суток** это от 0.03% до 5% в худшем случае. **Практического искажения фильтров свежести и TTL нет.** Моя формулировка в теле задачи («для долгих прогонов это смещение в часы») верна буквально, но подразумевала значимость, которой здесь нет. Снимаю это как основание для срочности. ## Где цена настоящая Аналитическая, а не фильтрующая: - **темп сбора по данным не восстановить** — все строки прогона выглядят одномоментными; - **порядок внутри прогона не восстановить** — отсюда же следовала невозможность бэкфилла `run_id` (#2701); - любое рассуждение вида «сначала увидели А, потом Б» в пределах прогона неверно, а выглядит правдоподобно. Плюс частный эффект: `scraped_at` и `last_seen_at` **согласованы между собой именно потому, что оба врут одинаково**. Если чинить, чинить надо оба сразу, иначе появится расхождение там, где его сейчас нет. ## Приоритет Понижаю: это не деньги и не искажение оценки, а потеря разрешения во времени. Чинить стоит вместе с любой следующей правкой писателя снимков, а не отдельным заходом. Формулировка задачи выше поправлена этим комментарием, а не переписана — чтобы было видно, что именно оказалось преувеличением.
Author
Collaborator

Инвентарь: схлопывается НЕ всё, и не всё схлопнутое — дефект

Замер на проде 2026-08-06, по каждому писателю содержательной колонки времени (строк / различных меток):

писатель колонка замер вердикт
save_listings listings_snapshots.observed_at run 3303 — 219/1 (7 мин работы), 3299 — 235/1, 3293 — 297/1, 3229 — 2643/55 дефект → починено (PR #2742)
save_listings listings.scraped_at, last_seen_at по часам 219/1, 235/1, 297/1, 150/1; eq == rows во всех корзинах дефект → починено (#2742)
_upsert_listing_source listing_sources.last_seen_at, last_scraped_at, matched_at по часам 219/1, 235/1, 297/1 дефект → починено (PR #2743)
avito/houses.py + матчер houses.last_scraped_at 206/21, 81/15, 735/25 дефект того же класса, НЕ починен (см. ниже)
avito/imv.py house_placement_history.scraped_at 115/7, 206/18, 80/4 дефект того же класса, НЕ починен
4 detail-провайдера listings.detail_enriched_at 153/153, 97/97, 19/19, 6/6 НЕ схлопывается — правка была бы холостой
listing_source_snapshot listing_source_snapshots.observed_at 89 827/1 схлопнуто ЧЕСТНО (один statement) — не трогаем
deactivate_stale_avito listings_snapshots.observed_at (status='stale') 225/2 схлопнуто ЧЕСТНО (data-modifying CTE)
sber_index sber_price_index.fetched_at 639/9 схлопнуто ЧЕСТНО (одна выкачка = много строк)
avito/imv, cian/valuation avito_imv_evaluations.fetched_at, external_valuations.fetched_at 46/46 не схлопывается (запись на вызов)

Что оказалось неверным в исходной формулировке

  1. «Метка одна на прогон» — нет, одна на транзакцию. Прогон 3229: 2643 строки на 55 меток, потому что городская развёртка зовёт save_listings на каждый гео-якорь. Внутри одного вызова метка действительно одна.
  2. «Механизм универсален, схлопываются все содержательные колонки» — нет. detail_enriched_at НЕ схлопывается ни в один из дней (153/153 3 августа): detail-писатели коммитят поштучно, у них транзакция = одна строка. Правка там ничего бы не изменила.
  3. first_seen_at у houses/sellers — это колонка с DEFAULT NOW(), писатель её не упоминает. Оставлена намеренно: «когда впервые увидели» законно привязано к прогону, а смена DEFAULT задела бы каждую будущую вставку ради разрешения, которого никто не читает.

Потребители, опирающиеся на схлопнутость

Не найдено. observed_at вообще не читается — ни бэкендом, ни фронтом, только пишется. Ни одного GROUP BY / DISTINCT по этим колонкам в коде нет.

Единственная зависимость — не от схлопнутости, а от равенства колонок между собой: миграция 161 использует WHERE last_seen_at > scraped_at. Поэтому clock_timestamp() (как в #2702/#2718) здесь НЕ годится: на проде clock_timestamp() = clock_timestamp()false, а statement_timestamp() = statement_timestamp()true. Взят statement_timestamp(): двигается от запроса к запросу внутри транзакции (замер: 1.2 с при неподвижном now()), но стабилен внутри запроса.

Отдельно: listings.last_seen_at = listing_sources.last_seen_at сегодня у 2407 пар из 2407. Поэтому починены обе половины — иначе вторая осталась бы замороженной на старте batch'а, и расхождение выросло бы с миллисекунд до длительности прогона. Это и есть причина, по которой правок две, а не одна.

Не тронуто осознанно

houses.last_scraped_at (206/21) и house_placement_history.scraped_at (115/7) — тот же класс, но другие модули (providers/avito/houses.py, providers/avito/imv.py), объёмы на два порядка меньше и ни одного потребителя внутрипрогонного разрешения. Отдельной задачей, если понадобится.

Соразмерность подтверждена

Фильтры свежести и TTL не искажены: смещение равно длительности прогона против окна в 14 суток — 0.03-5%. Приоритет, снятый комментарием выше, не восстанавливается.

PR: #2742 (listings + снимки + миграция 232 с датой перехода), #2743 (listing_sources).

## Инвентарь: схлопывается НЕ всё, и не всё схлопнутое — дефект Замер на проде 2026-08-06, по каждому писателю содержательной колонки времени (строк / различных меток): | писатель | колонка | замер | вердикт | |---|---|---|---| | `save_listings` | `listings_snapshots.observed_at` | run 3303 — 219/1 (7 мин работы), 3299 — 235/1, 3293 — 297/1, 3229 — 2643/55 | **дефект** → починено (PR #2742) | | `save_listings` | `listings.scraped_at`, `last_seen_at` | по часам 219/1, 235/1, 297/1, 150/1; `eq == rows` во всех корзинах | **дефект** → починено (#2742) | | `_upsert_listing_source` | `listing_sources.last_seen_at`, `last_scraped_at`, `matched_at` | по часам 219/1, 235/1, 297/1 | **дефект** → починено (PR #2743) | | `avito/houses.py` + матчер | `houses.last_scraped_at` | 206/21, 81/15, 735/25 | дефект того же класса, НЕ починен (см. ниже) | | `avito/imv.py` | `house_placement_history.scraped_at` | 115/7, 206/18, 80/4 | дефект того же класса, НЕ починен | | 4 detail-провайдера | `listings.detail_enriched_at` | 153/153, 97/97, 19/19, 6/6 | **НЕ схлопывается** — правка была бы холостой | | `listing_source_snapshot` | `listing_source_snapshots.observed_at` | 89 827/1 | схлопнуто ЧЕСТНО (один statement) — не трогаем | | `deactivate_stale_avito` | `listings_snapshots.observed_at` (status='stale') | 225/2 | схлопнуто ЧЕСТНО (data-modifying CTE) | | `sber_index` | `sber_price_index.fetched_at` | 639/9 | схлопнуто ЧЕСТНО (одна выкачка = много строк) | | `avito/imv`, `cian/valuation` | `avito_imv_evaluations.fetched_at`, `external_valuations.fetched_at` | 46/46 | не схлопывается (запись на вызов) | ### Что оказалось неверным в исходной формулировке 1. **«Метка одна на прогон»** — нет, **одна на транзакцию**. Прогон 3229: 2643 строки на 55 меток, потому что городская развёртка зовёт `save_listings` на каждый гео-якорь. Внутри одного вызова метка действительно одна. 2. **«Механизм универсален, схлопываются все содержательные колонки»** — нет. `detail_enriched_at` НЕ схлопывается ни в один из дней (153/153 3 августа): detail-писатели коммитят поштучно, у них транзакция = одна строка. Правка там ничего бы не изменила. 3. **`first_seen_at`** у `houses`/`sellers` — это колонка с `DEFAULT NOW()`, писатель её не упоминает. Оставлена намеренно: «когда впервые увидели» законно привязано к прогону, а смена DEFAULT задела бы каждую будущую вставку ради разрешения, которого никто не читает. ### Потребители, опирающиеся на схлопнутость Не найдено. `observed_at` **вообще не читается** — ни бэкендом, ни фронтом, только пишется. Ни одного `GROUP BY` / `DISTINCT` по этим колонкам в коде нет. Единственная зависимость — не от схлопнутости, а от **равенства колонок между собой**: миграция 161 использует `WHERE last_seen_at > scraped_at`. Поэтому `clock_timestamp()` (как в #2702/#2718) здесь НЕ годится: на проде `clock_timestamp() = clock_timestamp()` → **false**, а `statement_timestamp() = statement_timestamp()` → **true**. Взят `statement_timestamp()`: двигается от запроса к запросу внутри транзакции (замер: 1.2 с при неподвижном `now()`), но стабилен внутри запроса. Отдельно: `listings.last_seen_at = listing_sources.last_seen_at` сегодня у **2407 пар из 2407**. Поэтому починены обе половины — иначе вторая осталась бы замороженной на старте batch'а, и расхождение выросло бы с миллисекунд до длительности прогона. Это и есть причина, по которой правок две, а не одна. ### Не тронуто осознанно `houses.last_scraped_at` (206/21) и `house_placement_history.scraped_at` (115/7) — тот же класс, но другие модули (`providers/avito/houses.py`, `providers/avito/imv.py`), объёмы на два порядка меньше и ни одного потребителя внутрипрогонного разрешения. Отдельной задачей, если понадобится. ### Соразмерность подтверждена Фильтры свежести и TTL не искажены: смещение равно длительности прогона против окна в 14 суток — 0.03-5%. Приоритет, снятый комментарием выше, не восстанавливается. PR: #2742 (listings + снимки + миграция 232 с датой перехода), #2743 (listing_sources).
Author
Collaborator

Прод-верификация: метки различны

Обе правки в живом контейнере tradein-scraper (маркер statement_timestamp() — 5 вхождений в snapshot_writer.py, 6 в app/services/matching/listings.py), миграция 232 применена, комментарии колонок читаются из pg_description.

Первый писатель на новом коде — yandex_city_sweep_pervouralsk, прогон 3320, 2026-08-06 17:36:47.374 → 17:36:49.691 (2.3 с работы):

таблица строк различных меток равенство внутри строки
listings_snapshots.observed_at 57 57
listings.scraped_at / last_seen_at 57 57 / 57 scraped_at = last_seen_at у 57 из 57
listing_sources.last_seen_at / last_scraped_at 57 57 / 57 равны у 57 из 57

Соседние прогоны тех же суток на старом коде, для контраста: 3309 — 137 строк / 1 метка, 3304 — 140 / 1, 3303 — 219 / 1.

То есть выполнены оба условия сразу: писатель, отработавший дольше секунды, оставил различные метки у строк, и колонки, которые обязаны совпадать, совпали. Разрешение во времени восстановлено с «одна метка на транзакцию» до построчного.

Исторические строки остаются схлопнутыми и невосстановимы — граница смысла зафиксирована в COMMENT ON COLUMN (миграция 232).

## Прод-верификация: метки различны Обе правки в живом контейнере `tradein-scraper` (маркер `statement_timestamp()` — 5 вхождений в `snapshot_writer.py`, 6 в `app/services/matching/listings.py`), миграция 232 применена, комментарии колонок читаются из `pg_description`. Первый писатель на новом коде — `yandex_city_sweep_pervouralsk`, прогон **3320**, 2026-08-06 17:36:47.374 → 17:36:49.691 (2.3 с работы): | таблица | строк | различных меток | равенство внутри строки | |---|---|---|---| | `listings_snapshots.observed_at` | 57 | **57** | — | | `listings.scraped_at` / `last_seen_at` | 57 | **57** / **57** | `scraped_at = last_seen_at` у **57 из 57** | | `listing_sources.last_seen_at` / `last_scraped_at` | 57 | **57** / **57** | равны у **57 из 57** | Соседние прогоны тех же суток на старом коде, для контраста: 3309 — 137 строк / 1 метка, 3304 — 140 / 1, 3303 — 219 / 1. То есть выполнены оба условия сразу: писатель, отработавший дольше секунды, оставил различные метки у строк, и колонки, которые обязаны совпадать, совпали. Разрешение во времени восстановлено с «одна метка на транзакцию» до построчного. Исторические строки остаются схлопнутыми и невосстановимы — граница смысла зафиксирована в `COMMENT ON COLUMN` (миграция 232).
Author
Collaborator

ЗАКРЫТО — разрешение во времени восстановлено, проверка на проде 2026-08-07 09:0x UTC

Замер сделан заново, на прогонах, которых на момент авторской верификации ещё не было.

прогон  источник                              строк  различных меток observed_at
 3350   avito_newbuilding_sweep                440       440
 3344   cian_city_sweep                        124       124
 3320   yandex_city_sweep_pervouralsk          117       117
 3358   avito_city_sweep                       110       110
 3323   yandex_city_sweep_verkhnyaya_pyshma     57        57

для контраста, тот же день на СТАРОМ коде:
 3309   cian_city_sweep_serov                  137         1
 3303   (из тела задачи)                       219         1

listing_sources.last_seen_at по часам после правки: 134/134, 416/416, 124/124 — вторая половина не отстала, что и было причиной делать две правки, а не одну.

Схлопнутыми остались только те писатели, где это честно и заявлено: deactivate_stale_cian 161/1 и deactivate_stale_yandex 98/1 — data-modifying CTE, один statement.

Граница смысла зафиксирована в COMMENT ON COLUMN (миграция 232, применена 16:27). Исторические строки остаются схлопнутыми и невосстановимы — это записано в базе, а не в переписке.

Остаток, который я обязан назвать, чтобы он не потерялся

Инвентарь из комментария выше нашёл два писателя того же класса в других модулях, и они сознательно НЕ чинились. Проверил их сегодня — схлопывание никуда не делось:

houses.last_scraped_at            117 строк / 22 метки   (providers/avito/houses.py)
house_placement_history.scraped_at 126 строк /  8 меток  (providers/avito/imv.py)

Задача закрывается потому, что все три её пункта выполнены: писатель снимков починен, смена смысла зафиксирована датой, остальные писатели проверены (об этом и была просьба — «этот замер я не делал»). Два оставшихся — находка этой проверки, другой модуль и на два порядка меньший объём; чинить их стоит вместе со следующей правкой тех модулей, а не отдельным заходом.

PR: #2742, #2743.

## ЗАКРЫТО — разрешение во времени восстановлено, проверка на проде 2026-08-07 09:0x UTC Замер сделан заново, на прогонах, которых на момент авторской верификации ещё не было. ``` прогон источник строк различных меток observed_at 3350 avito_newbuilding_sweep 440 440 3344 cian_city_sweep 124 124 3320 yandex_city_sweep_pervouralsk 117 117 3358 avito_city_sweep 110 110 3323 yandex_city_sweep_verkhnyaya_pyshma 57 57 для контраста, тот же день на СТАРОМ коде: 3309 cian_city_sweep_serov 137 1 3303 (из тела задачи) 219 1 ``` `listing_sources.last_seen_at` по часам после правки: 134/134, 416/416, 124/124 — вторая половина не отстала, что и было причиной делать две правки, а не одну. Схлопнутыми остались только те писатели, где это **честно** и заявлено: `deactivate_stale_cian` 161/1 и `deactivate_stale_yandex` 98/1 — data-modifying CTE, один statement. Граница смысла зафиксирована в `COMMENT ON COLUMN` (миграция 232, применена 16:27). Исторические строки остаются схлопнутыми и невосстановимы — это записано в базе, а не в переписке. ### Остаток, который я обязан назвать, чтобы он не потерялся Инвентарь из комментария выше нашёл два писателя того же класса в других модулях, и они сознательно НЕ чинились. Проверил их сегодня — схлопывание никуда не делось: ``` houses.last_scraped_at 117 строк / 22 метки (providers/avito/houses.py) house_placement_history.scraped_at 126 строк / 8 меток (providers/avito/imv.py) ``` Задача закрывается потому, что все три её пункта выполнены: писатель снимков починен, смена смысла зафиксирована датой, остальные писатели **проверены** (об этом и была просьба — «этот замер я не делал»). Два оставшихся — находка этой проверки, другой модуль и на два порядка меньший объём; чинить их стоит вместе со следующей правкой тех модулей, а не отдельным заходом. PR: #2742, #2743.
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference: lekss361/gendesign#2731
No description provided.