Skip to content

_fix_timing.md

Latest commit

 

History

History
322 lines (253 loc) · 25 KB

_fix_timing.md

File metadata and controls

322 lines (253 loc) · 25 KB
Raw

_fix_timing — флакующая тайминговая проверка в test_search_case.py

Лана: флакующая проверка, которая портит доверие к полному прогону. Мои файлы: test_search_case.py, test_case_simulator.py. Git не трогал. Продакшн-код (assistant.py) НЕ ПРАВИЛ — ни на диске, ни на минуту: все диверсии сделаны подменой поведения В ПАМЯТИ до запуска набора, поэтому диверсия физически не могла остаться в боевом файле, даже если процесс умрёт.

0. Базовое состояние (замер, не оценка)

md5 ДО любых правок:

5a2f5a71efc8bf0db5d5372f242c9b6a  test_search_case.py
169a0d759e154b0116bdc9e050e0c0f4  test_case_simulator.py
16042cc80625599ea1fdf86d97f571d5  assistant.py   (НЕ мой, только контроль неизменности)

Одиночный прогон test_search_case.py на тихой машине: PASSED 33 / FAILED 0. Замер секции [7] в этом прогоне: было 29.9 мс, стало 71.0 мс -> отношение 2.37 при пороге naive*4 + 5 = 124.6 мс.

Python 3.13.14, sqlite3 3.50.4.

1. Почему падало именно ОТНОШЕНИЕ (замер, 12 пар подряд, _measure_timing.py D)

Каждый замер уже брался как минимум из 7 прогонов. Всё равно:

величина min max медиана разброс max/min
naive (1 LIKE), мс 29.26 97.96 31.59 3.35
fixed (3 LIKE), мс 61.31 84.47 74.30 1.38
отношение fixed/naive 0.77 2.79 2.23 3.64

Вывод числом: отношение дрожит СИЛЬНЕЕ каждого из двух замеров (3.64 против 3.35 и 1.38), потому что ошибки числителя и знаменателя независимы и умножаются. Запас до порога 4.0 по худшему наблюдённому отношению — всего 1.43x, и в полном прогоне свиты его съело: 17.7 против 77.8 мс = 4.40.

Отдельно: в упавшем прогоне сломался ЗНАМЕНАТЕЛЬ. naive показал 17.7 мс против 29.3 мс минимума на тихой машине — то есть минимум из 7 не защищает от того, что в другом процессе запрос окажется в 1.7 раза БЫСТРЕЕ (тёплые страницы, состояние турбо-частоты). Минимум устойчив только к замедлению, а отношение ломает и ускорение.

2. Что выбрано и почему: ЧИСЛО ШАГОВ SQLite вместо времени

Из четырёх предложенных вариантов взяты два, оба нетайминговые.

(а) Счётчик шагов виртуальной машины SQLite — Connection.set_progress_handler(fn, 1) вызывает fn на каждую инструкцию VDBE. Цена запроса, не зависящая от нагрузки ВООБЩЕ.

Детерминированность, 5 прогонов подряд (_measure_timing.py A):

naive (1 LIKE): [51177, 51148, 51148, 51148, 51148]   <- первый прогон +29 шагов (разбор схемы)
fixed (3 LIKE): [127679, 127678, 127678, 127678, 127678]

Первый вызов дороже на 0.06% из-за холодной схемы — поэтому в тесте перед замером идёт прогревочный прогон. После прогрева дрожание 0.0000%: _measure_timing2.py A дал 2 249 257 шагов на продакшн-пути пять раз подряд без единого расхождения.

Модель стоимости оказалась ТОЧНОЙ (_measure_timing3.py A), и это ключ к порогу:

k форм LIKE шагов на строку формула 1+3k отношение к k=1
1 51148 4.001 4 1.000
2 89501 7.001 7 1.750
3 127854 10.001 10 2.500
4 166207 13.001 13 3.250
5 204560 16.001 16 4.000
6 242913 19.001 19 4.750
8 319619 25.001 25 6.250

Отношение к одиночному LIKE = (1+3k)/4 с точностью до 0.001. Величина нормирована на строку, поэтому от РАЗМЕРА базы не зависит: вика вырастет с 12 784 до 20 000 фактов — отношение останется 2.500.

Порог поставлен 3.0 — между тремя формами (2.500) и четырьмя (3.250). Проверка стала СТРОЖЕ прежней, а не мягче: прежний порог 4.0 четвёртую форму пропускал (3.25 < 4.0), новый её ловит. Это подтверждено диверсией four_forms ниже.

(б) Число обращений к базе на один поиск — Connection.set_trace_callback, считаем SQL-операторы на реальном search_knowledge_corpus. Замер (_measure_timing3.py B):

ключей=1: операторов 4, SELECT 2, PRAGMA 2   -> 2.00 SELECT на ключ
ключей=2: операторов 6, SELECT 4, PRAGMA 2   -> 2.00 SELECT на ключ
ключей=4: операторов 10, SELECT 8, PRAGMA 2  -> 2.00 SELECT на ключ

Ровно одна выборка на ключ в вике и одна в архиве. Это структурный инвариант (_CORPUS_TOTAL_ROW_BUDGET=48 < _CORPUS_CANDIDATE_CAP=60, поэтому цикл по ключам никогда не обрывается), и он ловит класс регрессий, которого тайминг не видел вообще.

От медианы и от «больше прогонов» отказался: они уменьшают дрожание, но не убирают — источник в самой величине. Абсолютный тайминговый потолок ОСТАВЛЕН, потому что он ловит то, чего шаги не видят (см. п.5 про py_udf).

3. «Убери LIMIT» — задание подтвердилось, но не по той причине

Замер (_measure_timing2.py C, _measure_timing4.py C), три ключа:

  • по ШАГАМ снятие LIMIT стоит всего +11% (2 249 257 -> 2 485 523). Порог «не более чем втрое» этого не ловит и ловить не должен;
  • по ЧИСЛУ ЗАПРОСОВ ловится начисто: SELECT-ов 6 -> 2. Первый же ключ набирает _CORPUS_CANDIDATE_CAP=60 кандидатов, срабатывает break, и остальные два ключа врача В БАЗУ НЕ УХОДЯТ ВООБЩЕ;
  • выдача при этом становится ХУЖЕ, а не «просто дороже»: справка 20 строк -> 16, архив 20 строк -> 13. Последствие для врача — не задержка, а молча проигнорированные ключи его вопроса.

То есть «убери LIMIT -> проверка падает» верно, но ловит это счётчик ЗАПРОСОВ, а не счётчик цены. Формулировка задания «станет дороже» для этого кода неточна: candidate cap съедает почти всю разницу в цене и превращает её в потерю полноты.

4. Что изменено

test_search_case.py, секция [7] — сравнение двух таймингов заменено на:

  • счётчик цены детерминирован: два прогона дают одно число — сам анти-флак-инвариант теперь проверяется, а не предполагается;
  • счётчик действительно считает, а не молчит (шагов >= числа строк) — без этого при неработающем progress handler оба числа стали бы нулями, 0 <= 0*3 прошло бы, и проверка цены стала бы пустышкой, зелёной при любой поломке. Диверсия dead_counter показала ровно это: отношение напечаталось как 0.000 и прошло, поймала только проверка живости;
  • три формы дороже одной не более чем втрое — замер 2.496 при пороге 3.0;
  • на каждую строку зовётся только встроенный like, без питона — по опкодам EXPLAIN (p4 даёт like(2) против pylower(1)). Добавлено ПОСЛЕ того, как диверсия py_udf прошла оба потолка цены;
  • абсолютный потолок по часам ОСТАВЛЕН (fixed_ms < 500): он ловит то, чего шаги не видят — если медленным станет диск или база уйдёт в WAL под чужим писателем, число шагов не изменится, а врач будет ждать секунды. Под нагрузкой замерено max 88.4 мс, запас 5.7x;
  • вариантов LIKE ровно три — оставлено как было.

test_search_case.py, новая секция [7a] — продакшн-путь search_knowledge_corpus под трассировкой операторов:

  • справка по трём ключам не пуста — чтобы трасса не «проходила» на пустом результате;
  • на каждый ключ по одной выборке в вике и в архиве (6 SELECT на 3 ключа);
  • каждая выборка ограничена LIMIT;
  • строк на ключ не больше запаса кандидатов (60) — ловит и снятый, и раздутый LIMIT.

Трассирующее соединение попутно уводит боевые базы в mode=ro: продакшн открывает их через sqlite3.connect("stomat_wiki.db"), то есть НА ЗАПИСЬ, а на время замера эта ручка физически не пишет.

test_case_simulator.py — ruff F841: _corpus_error = sqlite_error = RuntimeError(...) -> _corpus_error = RuntimeError(...). Сама проверка не тронута, набор 24/0.

Заодно в test_search_case.py убраны два ruff E741 (l -> ln). По НАБОРУ ПРАВИЛ ПО УМОЛЧАНИЮ (E4/E7/E9/F — тот, которым найден F841) в моих двух файлах остаётся только E402 (3 шт.): репозиторный паттерн, config.DB_PATH обязан ставиться до import database; по всему репозиторию E402 встречается 128 раз.

Если расширить до --select E,F, всплывает E501 (строка длиннее 88): в моих файлах 25 штук, из них 5 добавил я, остальные были. E501 в наборе по умолчанию НЕ проверяется, и файл в этом стиле написан целиком, поэтому переносить не стал — вместо 5 переносов ради правила, которое лид не включал, риск сломать рабочий код выше пользы. Если правило нужно включить, это отдельная правка по всему репозиторию, не по двум файлам.

Цена по времени прогона (_measure_timing6.py, замер, не оценка): добавлено 1.12–1.26 с, убрано 0.36–0.58 с (тайминг naive больше не нужен), чистый прирост +0.56…+0.86 с. Весь набор целиком: 6.3–10.8 с.

5. Саботаж: 7 диверсий, все семантические, все поймались

Все диверсии — подмена поведения продакшна В ПАМЯТИ (_sabotage_timing.py), файл assistant.py не открывался на запись ни разу. Ни одна не ломает синтаксис.

# диверсия что сломано провалов ловит
1 four_forms like_any_case отдаёт 4 формы вместо 3 8 цена x3.24 при пороге 3.0 (прежний порог 4.0 это ПРОПУСКАЛ)
2 no_limit _rows_per_keyword -> 10^9, LIMIT фактически снят 2 SELECT-ов 3 вместо 6; LIMIT 1000000000 против запаса 60
3 budget_over_cap бюджет строк 40 на ключ > запаса кандидатов 60 1 SELECT-ов 4 вместо 6 — третий ключ врача не искали
4 dead_counter счётчик шагов молчит (фабрика соединения) 1 проверка живости счётчика; отношение 0.000 прошло бы
5 single_form правку регистра откатили, поиск снова ASCII-only 12 секции [2] [3] [4]: ВНЧС снова 0 из 88
6 py_udf складывание регистра через питоновскую функцию 5 опкоды: ['like(2)', 'pylower(1)']
7 double_query повтор выборки «на случай database is locked» 1 SELECT-ов 12 вместо 6

Базовый прогон через тот же драйвер: 40/0, код 0.

Подробности по двум важным:

four_forms — печать теста: было 51148 шагов SQLite (4.001 на строку), стало 165767 (12.967 на строку), отношение 3.241. Порог 3.0 -> провал. Прежняя формулировка (fixed_ms <= naive_ms*4 + 5) на 3.241 прошла бы: это и есть доказательство, что новая проверка не пустышка и не ослабление.

py_udf — единственная, где НОВАЯ ПРОВЕРКА ЦЕНЫ ПРОМАХНУЛАСЬ в первой редакции: шагов x1.252, по часам 107.9 мс при пороге 500 — прошли оба потолка. Набор был красным только за счёт проверок формы условия (4 провала). Причина: счётчик шагов считает КОЛИЧЕСТВО инструкций, а не их цену, а обратный вызов в питон стоит дорого за шаг (158 мс на 17 опкодов против 85 мс на 24). Дописал проверку по опкодам EXPLAIN (p4 = like(2) у настоящего запроса, pylower(1) у диверсии), повторил диверсию: провалов стало 5, включая новую. Это же соответствует уже принятому в продакшне решению — в докстринге like_any_case написано, что три формы в одном запросе выбраны как более дешёвая альтернатива create_function.

6. Доказательство, что НЕ флакует

10 прогонов подряд под нагрузкой (_flake_timing.py): 6 процессов полного скана боевых баз плюс 2 соседних набора того же модуля, перезапускаемые по мере завершения.

  #  PASSED  FAILED  шагов было  шагов стало  отношение     мс  SELECT
  1      40       0       51148       127678      2.496   63.6       6
  2      40       0       51148       127678      2.496   67.1       6
  3      40       0       51148       127678      2.496   88.4       6
  4      40       0       51148       127678      2.496   65.9       6
  5      40       0       51148       127678      2.496   74.9       6
  6      40       0       51148       127678      2.496   62.3       6
  7      40       0       51148       127678      2.496   71.4       6
  8      40       0       51148       127678      2.496   80.6       6
  9      40       0       51148       127678      2.496   58.7       6
 10      40       0       51148       127678      2.496   64.7       6

зелёных прогонов: 10 из 10
отношение шагов: min=2.496 max=2.496 разброс=1.0000
пары (шагов было, шагов стало): {(51148, 127678)}
тайминг по часам под нагрузкой: min=58.7 max=88.4 мс разброс=1.51 при пороге 500

Пара чисел (51148, 127678) совпала во всех десяти прогонах ПОБИТОВО.

Контрольный опыт: старая метрика под той же нагрузкой (_flake_old_metric.py), в одном процессе считаются обе метрики. 6 сканеров:

старая метрика (отношение мс):   min=0.829 max=2.843 разброс=3.43, провалов 0 из 10
новая метрика (отношение шагов): min=2.496 max=2.496 разброс=1.0000, провалов 0 из 10
знаменатель старой метрики (naive мс): min=29.38 max=76.42 разброс=2.60

16 сканеров (тяжелее):

старая метрика: min=1.499 max=2.519 разброс=1.68, провалов 0 из 10
новая метрика:  min=2.496 max=2.496 разброс=1.0000, провалов 0 из 10

Неожиданный результат, который стоит знать: под ТЯЖЁЛОЙ равномерной нагрузкой старая метрика ведёт себя СПОКОЙНЕЕ (1.68), чем под средней (3.43). Значит флак вызывает не высокая нагрузка, а НЕРАВНОМЕРНАЯ: когда все процессы тормозят одинаково, отношение сохраняется, а ломает его удачный/неудачный квант в одном из двух замеров. Отсюда же понятно, почему в упавшем прогоне свиты naive оказался 17.7 мс — быстрее, чем на тихой машине.

Итого по новой метрике: 35 наблюдений (5 тихих + 30 под нагрузкой), все ровно 2.496, разброс 1.0000. Дрожания не осталось не «мало», а структурно: величина целочисленная и детерминированная.

7. Восстановление и доказательство

Диверсий на диске не было ни одной: продакшн правился только в памяти дочернего процесса. Файлов .bak не создавал, удалять нечего (fd -e bak пусто).

md5 ПОСЛЕ всех работ:

713e5bb98233c1e57ffbd73f8dd3ad6b  test_search_case.py     (мой, изменён осознанно)
3a59c94052663a19df7279811fe2ab84  test_case_simulator.py  (мой, ruff F841)
cc9ff38d11a5e6d9f9f59edcfe6547ad  assistant.py            <- ИЗМЕНИЛСЯ, но НЕ МНОЙ

Про assistant.py: на старте 16042cc80625599ea1fdf86d97f571d5, сейчас cc9ff38d11a5e6d9f9f59edcfe6547ad, mtime 13:54:43. Мои последние записи на диск — test_search_case.py в 13:46, после этого я в файлы не писал (в 13:54 шёл прогон нагрузки). Правка чужая, рядом работает другой агент. Мой финальный зелёный прогон сделан НА НОВОМ assistant.py, то есть чужая правка мои проверки не сломала.

Финальные прогоны (после чужой правки продакшна):

набор результат
test_search_case.py 40 / 0 (было 33 / 0)
test_case_simulator.py 24 / 0
test_rag_quality.py 53 / 0
test_isolation.py 198 / 0 (сторож mode=ro мою правку принял)
test_import_safety.py 448 / 0

run_all_tests.py не запускал — по заданию.

8. Что осталось непроверенным (честно)

  1. Не воспроизвёл сам флак. За 30 наблюдений под нагрузкой старое отношение не перевалило 4.0 (максимум 2.843). Доказано не «старая проверка падает по команде», а что её разброс 3.43x при запасе 1.43x до порога, то есть падение — вопрос времени, и что у новой метрики разброс 1.0000.
  2. Порог 3.0 держится на модели 1+3k конкретной сборки SQLite (3.50.4). Формула подтверждена замером на семи значениях k с точностью 0.001, но если sqlite поменяет программу LIKE, коэффициент 3 шага на LIKE поплывёт. Провал будет громким и с числом в детали, а не молчаливым. На другой машине (бот живёт не здесь) не проверял.
  3. Диверсии сделаны monkeypatch-ем, а не правкой файла. Семантически это то же (подменяется поведение продакшн-функции, которое тест и проверяет), но байты assistant.py я не менял ни на секунду — сознательный выбор: править чужой файл запрещено, и в волне 2 два проверяющих умерли, оставив диверсию в боевом коде.
  4. _CORPUS_CANDIDATE_CAP-инвариант проверен на 1/2/3/4 ключах. Что будет при ключах больше 7 (rows_per_keyword упирается в минимум 8), не замерял.
  5. Секция [7a] всё ещё ходит в боевые базы (через ro-соединение). Живого писателя рядом не было; поведение при конкурентной записи в вику не проверял.
  6. Абсолютный потолок 500 мс не срабатывал ни разу ни в одной диверсии — под нагрузкой максимум 88.4 мс, у py_udf 107.9 мс. Он оставлен как страховка от медленного диска, но его теми я не доказал.

Для лида

  • Правок вне моих файлов не требуется. Продакшн не тронут.
  • assistant.py изменился в 13:54:43 не мной (см. п.7) — если это неожиданно, стоит спросить владельца той полосы.
  • Черновики замеров (_measure_timing*.py, _sabotage_timing.py, _load_timing.py, _flake_timing.py, _flake_old_metric.py) в diff НЕ ПОПАДУТ: .gitignore глушит _*.py. Все числа выше воспроизводятся их запуском; сами скрипты самоограничены по времени и добивают дочерние процессы в finally.
  • Ничего запущенного за собой не оставил: все сканеры нагрузки имеют дедлайн в argv и добиваются в finally, проверено Get-CimInstance Win32_Process — из питонов живы только verify_daily_cleanup.py (12:09, чужой) и h8_posctrl.py (не мой).
  • Если понадобится ещё строже: порог 3.0 можно опустить до 2.6 (запас 4% над замером 2.496) — тогда ловится и лишний встроенный LOWER() (2.746). Не стал: 4% запаса на случай смены сборки sqlite мало.