Обычная разработка

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

Программа идёт часами и молчит

Самый частый и самый обидный случай: процесс работает, процессор занят, и понять — считает он или зациклился — нечем. Снаружи живой прогон и зависший выглядят одинаково.

Записи отвечают на это прямо, и ответ не требует вычислений. Каждый вызов даёт две строки, связанные общим id: вход ("p":"in") и завершение ("p":"out"). Строка входа, у которой нет парной строки выхода, означает ровно одно: вызов вошёл и не вернулся — зависание, падение или жёсткий выход.

Искать непарные id руками не нужно: инструмент уже это сделал. В ответе и trace, и trace-stats есть поле in_flight:

  "in_flight": [],
  "in_flight_truncated": false,

Пусто — все вызовы вернулись. Непусто — там имя функции, номер вызова, время входа, поток и ядро. Заодно видно, какая функция звалась последней и с какими доводами: fn, a и k стоят в строке входа, которая уже записана, — ждать завершения вызова, чтобы что-то узнать, не нужно.

Это и есть причина, по которой записей две, а не одна. Цена названа прямо: две записи на вызов — вдвое больший объём. За что заплачено: запись «одной строкой по завершении» вызов, который завис, упал или вышел жёстко, не может записать вообще — он в ней просто отсутствует и неотличим от вызова, которого не было.

В многопоточной программе смотрите th и ci. Отобрать один поток — --thread <метка>. Сводка по потокам есть в trace-stats:

  "by_thread": [
    { "thread": "2864987.129949101195776", "count": 7, "functions": 3, "cpus": [] }
  ],

cpus здесь пусто, потому что прогон был на Python, а там номер ядра всегда «неизвестно». Подробности — Языки.

Чтобы не утонуть в записях. Обмазывать горячий файл целиком нельзя: нужное утонет в шуме. Обмазывайте выбранные функции — wrap-functions вместо wrap-file.

Считайте, прежде чем возражать объёмом. Типичное возражение — «получатся гигабайты» — почти всегда ощущение, а не счёт. Замер: семь вызовов дали 14 строк и 1887 байт, то есть около 270 байт на вызов при коротких доводах. Сто тысяч вызовов — примерно 27 МБ. Ваше число будет другим (длина зависит от ваших доводов и результатов, обрезаемых на 200 знаках) — померьте на малом прогоне и умножьте.

«Оно раньше работало»

Прогнали до правки, прогнали после, сравнили записи. Ответ получается не «тесты красные», а вот эти сорок вызовов теперь ведут себя иначе — с доводами и результатами обеих сторон.

Сравнение при этом ваше: команды «сличить два прогона» у инструмента нет. Есть trace, дальше — обычные средства сравнения файлов.

Обнулите поля, которые меняются сами по себе, иначе разными окажутся все записи до одной: t (время входа), id (номер вызова), d (длительность), а также ci и th. Всё остальное — fn, a, k, r, x — от прогона к прогону меняться не должно, и вот их расхождение и есть ответ.

Например так:

ouroboros trace debug.info --limit 1000 \
  | jq -S '[.records[] | {name, args, kwargs, outcome_kind, outcome}]' > до.json

Отдельно полезно на правках, где тесты зелёные, а поведение изменилось: тест проверяет то, что кто-то придумал заранее, записи — то, что было.

Отлаживать одно и то же место дважды

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

Подробно, вместе с оговорками про скрытое состояние, — на странице Прологировать чужой код.

Найти медленное

ouroboros trace debug.info --min-duration 0.1

Оставит только вызовы дольше 0,1 секунды. Сводка trace-stats при этом даёт min/max/mean/total по каждой функции — и это настоящие длительности каждого вызова из поля d, а не вычитание меток времени.

Помните ограничение: это длительности обмазанного прогона. Для «какая функция подозрительно долгая» годится, для «сколько это стоит в бою» — нет.

Что запускалось

ouroboros execute дописывает в debug.info по служебной записи на каждую запущенную команду — саму команду, код возврата и вывод:

{"p":"exec","cmd":["python3","stats.py"],"rc":0,"out":"20.0\n","err":""}

Так файл остаётся однородным JSONL и единственным местом, где написано, что запускалось и чем кончилось. Читалка такие строки пропускает: у них p не in и не out, событием вызова они не являются. Испорченными (malformed) считаются только строки, которые не разбираются как JSON, или порванные.

Чего не стоит делать

Обмазывать всё подряд на горячем пути. Полезные записи утонут, и программа заметно замедлится. Обмазывайте выбранные функции.

Забывать, что обмазка остаётся в коде. Она не снимается сама, и finish её тоже не снимает. Перед тем как что-то уйдёт наружу, посмотрите глазами: git status, git diff, а заодно поищите файл помощника рядом с обмазанным.

Читать d как настоящую цену вызова. Обмазка меняет время работы программы, поэтому d — длительность обмазанного прогона, а не обычного.

Копить debug.info между прогонами. Файл только дописывается. Если нужна чистая запись — удалите его перед прогоном, иначе прошлый прогон подмешается к нынешнему и calls_parsed соврёт.

Принимать записи за доказательство. Они говорят, что было, а не что должно быть. Подробнее — Границы.