Профилирование с cProfile и py-spy: измерьте продакшен-нагрузку до правок кода

cProfile: детерминированная трассировка и что искажает оверхед

cProfile — детерминированный трассировщик: он регистрирует C-уровневый профильный хук (механика lsprof за sys.setprofile), срабатывающий на каждом вызове и возврате функции, и копит счётчики и таймеры по функциям. Ничего не пропускается — в этом привлекательность, — но каждый вызов платит фиксированный налог на учёт, поэтому программа целиком обычно работает в 1.3-2 раза медленнее. Искажение неравномерно. Фиксированная цена на вызов огромна относительно хелпера на 200 нс, вызванного десять миллионов раз, и ничтожна относительно 50-миллисекундного запроса к базе, вызванного дважды. Поэтому мелкие горячие Python-функции выглядят хуже, чем есть, и рейтинг «главных виновников» гнётся к числу вызовов, а не к реальной стоимости.

Чтение вывода — отдельный навык: tottime — собственное время (без вызываемых), cumtime — включающее. Сортируйте по cumtime, чтобы найти дорогое поддерево, затем по tottime внутри него, чтобы найти, где реально горят циклы. pstats режет программно; snakeviz показывает те же данные интерактивно.

import cProfile, pstats

cProfile.run("handle_request(req)", "out.prof")
p = pstats.Stats("out.prof")
p.sort_stats("cumulative").print_stats(12)  # найти дорогое поддерево
p.sort_stats("tottime").print_stats(12)     # найти собственную стоимость внутри

Две слепые зоны структурны. Первая: внутренности C невидимы — json.dumps или операция numpy выглядят одной непрозрачной строкой: общее время есть, разбивки внутри нет. Вторая: потоки — по умолчанию cProfile наблюдает только поток, в котором запущен; рабочие потоки идут непрофилированными, пока каждый не установит свой профилировщик. Под asyncio метод запуска цикла событий проглатывает всё в один cumtime, и пер-корутинная атрибуция мутнеет.

py-spy: сэмплирование снаружи процесса

py-spy переворачивает сделку. Он работает отдельным процессом: читает память цели — process_vm_readv/ptrace на Linux, mach-API на macOS, — находит состояния потоков интерпретатора и обходит структуры фреймов, восстанавливая каждый Python-стек примерно 100 раз в секунду. Без изменения кода, без импорта, без рестарта: подключение по PID к процессу, запущенному задолго до того, как вы узнали о проблеме. Цель приостанавливается на микросекунды на сэмпл, так что оверхед — около 1%. Безопасно против продакшена.

Три подкоманды покрывают полевой процесс:

• py-spy top --pid 4137 — живой вид в стиле htop: какие функции владеют сэмплами прямо сейчас.
• py-spy record -o prof.svg --pid 4137 --duration 60 — флеймграф; добавьте --native, чтобы вплести C-фреймы (именно так сериализатор из хука стал видимым), --idle — чтобы включить заблокированные потоки.
• py-spy dump --pid 4137 — одномоментный стек каждого потока: инструмент для зависшего процесса. Воркер на 0% CPU, переставший разбирать очередь, диагностируется за секунды — видно, на каком именно захвате лока или чтении сокета припаркован каждый поток.

Честная оговорка: сэмплирование статистично. Всплеск на 5 мс раз в минуту на 100 Гц может не попасть в сэмплы вовсе; нужно достаточно стенового времени на исследуемом поведении, а латентность редких событий требует трейсинга, не профилирования.

timeit и ложь микробенчмарков

timeit отключает GC и сообщает лучший из N повторов — он по замыслу меряет тёпло-кэшевый, разогнанный турбо-бустом идеал изолированного сниппета. Реальный сервис гоняет тот же код с холодными кэшами, перемешанной работой, вытесняющей предсказатель ветвлений, частотным скейлингом и фрагментированным аллокатором. Выигрыш в 30% по timeit может быть невидим на p99. Используйте его, чтобы сравнить две реализации одной маленькой операции при одинаковой лжи, — и никогда, чтобы предсказать латентность сервиса.

Дисциплина

Прежде чем потянуться к профилировщику, спроси себя: совпадает ли эта среда с продакшеном? Реальные размеры payload, реальная конкурентность, реальные распределения данных, реальные хитрейты кэшей. Синтетический цикл на дев-машине — это другая программа, случайно разделяющая исходники. Рабочий порядок: py-spy против продакшена (или реплея прод-трафика), чтобы найти где; cProfile и timeit локально, чтобы итерироваться над почему; затем перемерить p99 после деплоя — профилировщик это улика, метрика SLO — приговор.