Что записывать и как найти нужное в записанном

Два вопроса, которые встают сразу после первого прогона. Первый: обмазывать ли весь файл. Второй: что делать с трассой, в которой записей больше, чем можно прочитать глазами.

Часть первая: сколько обмазывать

Весь файл

ouroboros wrap-file discount.py

{"ok": true, "path": "discount.py", "language": "python", "functions_wrapped": 3, "runtime_header": "ouroboros_runtime.py"}

Годится, когда файл небольшой и непонятно, где искать. Именно с этого начинают.

Только названные функции

ouroboros wrap-functions partial.py discount_rate

{"ok": true, "path": "partial.py", "language": "python", "functions_requested": ["discount_rate"], "functions_wrapped": 1, "runtime_header": "ouroboros_runtime.py"}

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

Когда брать второе

Функция зовётся очень часто. Обмазать то, что вызывается миллион раз за прогон, — значит получить два миллиона строк, среди которых нужные не найти. И записи не бесплатны: каждая — это запись в файл.

Файл большой, а интересен один путь. Записи от сорока посторонних функций не помогают, а мешают: их надо отфильтровать, и в сводке они занимают место.

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

Порядок на практике получается такой: обмазали файл целиком → посмотрели сводку → увидели, где происходит интересное → откатили → обмазали три функции → сняли чистую трассу.

Часть вторая: как спрашивать у трассы

Команда trace умеет шесть отборов, и их можно сочетать.

По имени функции

ouroboros trace ./debug.info --function discount_rate

Совпадение по куску имени, без учёта регистра. У Python имя полное — например, Cart.checkout для метода, — поэтому --function Cart даст все методы класса.

По содержимому доводов и исхода

ouroboros trace ./debug.info --contains 10000

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

{
  "matched": 2,
  "records": [
    { "name": "discount_rate", "args": "10000, False", "outcome": "0.1" },
    { "name": "apply_discount", "args": "10000", "outcome": "9000.0" }
  ]
}

Это самый полезный отбор при разборе падения: вы знаете подозрительное значение и ищете все вызовы, где оно встретилось.

По исходу

ouroboros trace ./debug.info --outcome raised

Три значения: result — вызов вернул значение, raised — бросил исключение, unknown — в записи не оказалось ни того ни другого.

По длительности

ouroboros trace ./debug.info --min-duration 0.0001

Оставляет вызовы, которые заняли не меньше указанного числа секунд. Так ищут медленные места. На разобранном прогоне под этот порог подошли три вызова: main, внутри которого происходило всё остальное, и два вызова apply_discount. Порог подбирают под свой прогон — на другой машине те же вызовы займут другое время.

Вызовы, у которых длительность не записана, при этом отборе отбрасываются.

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

По потоку

ouroboros trace ./debug.info --thread 7.129140652823040

Точное совпадение с полем th. Нужно, когда в одну трассу пишут несколько потоков или процессов: без такого отбора их записи перемешаны.

Какие потоки вообще были — видно в сводке:

"by_thread": [
  { "thread": "7.129140652823040", "count": 9, "functions": 3, "cpus": [] }
]

По образцу

ouroboros trace ./debug.info --regex --function '^(discount|apply)_'

Ключ --regex заставляет считать --function и --contains регулярными выражениями вместо кусков строки. На разобранном прогоне этот образец даёт восемь вызовов из девяти — все, кроме main.

Сколько показывать

Записей может быть много, поэтому у вывода есть предел — по умолчанию 200. Два ключа управляют этим:

• --tail 20 — оставить только последние двадцать подошедших. В ответе тогда matched считает все подошедшие, а returned — сколько показано. Удобно, когда интересен конец прогона.
• --limit и --cursor — читать частями. Если подошедших больше предела, в ответе приходит next_cursor; передав его в следующий вызов, получаете следующую часть. Когда всё прочитано, next_cursor равен null.

Часть третья: с чего начинать разбор

Порядок, который экономит время:

1. Сводка целиком. trace-stats без отборов. Сразу видно: сколько вызовов, какие функции живые, у кого есть raised, пуст ли in_flight.
2. Что упало. trace --outcome raised. Если что-то бросало — начинать отсюда: доводы падавшего вызова обычно и есть ответ.
3. Что долго. trace --min-duration <порог>. Порог берут из duration_seconds в сводке — например, чуть меньше max.
4. Что вокруг подозрительного значения. trace --contains <значение>.

Первые два шага закрывают большинство разборов.

Чего отбор не сделает

Отбор работает с тем, что записано. Он не покажет вызов, которого в прогоне не было, и не предупредит, что такого вызова не было.

Отсюда простое требование к прогону: записывать надо на той нагрузке, про которую вы собираетесь что-то утверждать. Прогнали на трёх удобных значениях — получите записи про три удобных значения. Ветвь, в которую не зашли, промолчит, и молчание это неотличимо от «там всё в порядке».

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