Профилирование производительности в Python через cProfile и py-spy локализация узких мест против оптимизации на глазок

Разработчик смотрит на медленный сервис, и взгляд сам цепляется к циклу, который "точно" виноват: три вложенных прохода, ну конечно здесь. Через неделю, после переписанного цикла, время отклика не меняется ни на миллисекунду, потому что настоящий виновник сидел в разборе JSON-ответа на два мегабайта и никто его не подозревал. Интуиция в вопросах производительности ошибается с завидной стабильностью: она всегда указывает на код, который автор любит переписывать, а не на код, который реально ест время. Против неё есть два честных приёма: детерминированный профиль, записывающий каждый вызов функции, и семплирование стека живого процесса. Ниже разбор cProfile и py-spy, их сильных сторон, слепых зон и порядок работы, при котором узкое место находится за вечер, а не за неделю споров о стиле.

Как cProfile записывает каждый вызов и что выдаёт pstats

cProfile стоит в стандартной библиотеке и работает детерминированно: перехватывает каждое событие вызова, возврата и исключения, измеряя интервалы между событиями. Профилировщик написан на C, поэтому цена наблюдения умеренная, а старший брат с тем же интерфейсом, чистый Python-модуль profile, давно отправлен в отставку и с версии 3.15 официально осуждается с удалением в 3.17. Быстрее всего запустить съёмку прямо из командной строки:

python -m cProfile -o app.prof app.py

Отчёт читается модулем pstats, и здесь же живёт главное умение, отличающее инженера от оптимизатора на глазок: правильная сортировка. Строки можно сортировать по ключам через enum SortKey из pstats, а фильтр вывода оставляет верхушку:

import pstats

stats = pstats.Stats("app.prof")
stats.sort_stats("tottime").print_stats(15)

Для точечной съёмки фрагмента кода профилировщик используется как контекстный менеджер, тогда под наблюдение попадает только интересный участок:

import cProfile

with cProfile.Profile() as pr:
    process_orders()

pr.dump_stats("orders.prof")

Дамп открывается позже, в том числе визуализаторами вроде SnakeViz, которые превращают таблицу в интерактивное дерево вызовов и позволяют свернуть шумные ветки одним щелчком.

Недооценённая связка pstats это методы print_callers и print_callees. Сортировка отвечает на вопрос "кто тратит", а эти таблицы на вопрос "кто зовёт": найдя подозреваемую функцию, у отчёта спрашивают всех её заказчиков, и часто выясняется, что восемьдесят процентов вызовов приходит из одного неожиданного места, которое и есть настоящий вход в проблему. Командная строка тоже умеет сортировать на лету, флаг -s cumtime у python -m cProfile выстроит отчёт по кумулятивному времени без всякого кода.

Что означают колонки отчёта и почему tottime честнее cumtime

Отчёт pstats пугает новичка шестью колонками, хотя читается за минуту. ncalls это счётчик вызовов, для рекурсивных функций он выглядит как дробь "128/64", где первое число общие вызовы, а второе без учёта вложенных. tottime показывает время, проведённое внутри самой функции без детей, cumtime складывает и её работу, и работу всех вызванных ею функций, percall делит оба значения на число вызовов:

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
128/64    0.420    0.003    0.910    0.014 app.py:42(build_tree)
84000    0.310    0.000    0.310    0.000 json/decoder.py:355(decode)
2400     0.190    0.000    0.480    0.000 requests/models.py:833(json)

Сортировка по cumtime честно указывает на вершину цепочки, но там всегда оказывается main, так происходит, потому что всё время программы стекается вверх по цепочке вызовов. Настоящие кандидаты на оптимизацию ищутся сортировкой по tottime: она выделяет функции, которые работают сами, а не нанимают работяг. Второе правило чтения: смотрят пары строк и связывают счётчик вызовов с временем. Восемьдесят четыре тысячи вызовов разбора JSON по четыре микросекунды это не "медленный json", это архитектурный вопрос "почему мы парсим одно и то же восемьдесят четыре тысячи раз". Профиль отвечает на вопрос "где", а вопрос "почему" остаётся за инженером.

Слепые зоны детерминированного профиля и где он обманывает

Первое ограничение физическое: cProfile подключается в момент запуска процесса, и к уже работающему продакшен-сервису прицепиться нельзя, его нужно перезапускать под наблюдением. Для сервиса, который нельзя трогать, это сразу закрывает вопрос. Второе ограничение про нативный код: вызов расширения на C виден в отчёте одной строкой с cumtime, но внутренности его не видны, и numpy, тратящий время внутри своего цикла, выглядит безликой линией, внутри которой спрятана вся правда. Третье ограничение про ожидание: если функция висит в socket.recv, профилировщик честно запишет, что время прошло внутри recv, и не скажет, виноват ли код, сеть или соседний сервис на том же хосте. Четвёртое: накладные расходы на каждое событие искажают микромир, функция из миллиона дешёвых вызовов показывает время, которого без профилировщика не существует, поэтому верить детерминированным цифрам на наносекундных операциях нельзя. Споры о том, что видит глобальная блокировка и где ждут потоки, профиль тоже не решает, для этого снимают отдельные стеки.

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

py-spy и семплирование стека живого процесса без перезапуска

py-spy подходит к задаче статистически. Вместо регистрации каждого события он периодически считывает стек наблюдаемого процесса, по умолчанию сто раз в секунду, и по набору снимков восстанавливает картину: функция, чья полоса набрала ширину, там и живёт время. Инструмент написан на Rust, распространяется одним бинарником и не требует ставить что-либо в окружение самого приложения, достаточно номера процесса. К работающему сервису цепляются тремя командами:

py-spy top --pid 4831
py-spy record --pid 4831 -o flame.svg --duration 60
py-spy dump --pid 4831

top открывает живую консоль с самыми горячими функциями, record за указанную минуту пишет флэймграф, картину из горизонтальных полос, где ширина означает долю времени, а сплошные широкие плато это и есть узкое место. dump мгновенно печатает стеки всех потоков, скорая помощь при зависшем процессе: сначала смотрят, где именно стоят потоки, и только потом перезапускают. Флаг native расширяет снимки внутрь расширений на C, то есть закрывает вторую слепую зону детерминированного профиля, флаг subprocesses подключает дочерние процессы, а gil показывает, сколько времени процесс реально держал глобальную блокировку, что отделяет вычислительную нагрузку от ожидания. Для анализа вне консоли py-spy record умеет писать отчёт в формате speedscope, который открывается в браузерных просмотрщиках и позволяет листать стеки как временную шкалу, а флаг function сворачивает снимки по функциям вместо строк и очищает картину от полос вида module.py:14 и module.py:15. Команда dump с флагом locals печатает и локальные переменные кадров, превращаясь в полноценный снимок состояния зависшего процесса. Плотность съёмки задаётся флагом rate: окно наблюдения в двадцать секунд заслуживает двести снимков в секунду, чтобы короткие всплески не потерялись.

Семплирование платит точностью: пауза при каждом снимке короткая и для веб-сервиса незаметная, но редкие короткие вызовы в статистику почти не попадают. Актуальная ветка 0.4 дожила до версии 0.4.2 весной 2026 года, сборки выходят для Windows и Linux на x86-64 и ARM, и на Linux для доступа к чужому процессу потребуются права root или разрешение ptrace.

Как изменилась карта инструментов профилирования после Python 3.14

С октября 2025 года, с релизом Python 3.14, стандартная библиотека получила собственный пакет profiling с двумя модулями. tracing это тот же детерминированный профилировщик, знакомый по cProfile, который остался рабочим псевдонимом для совместимости. sampling это встроенный семплирующий профайлер, реализованный прямо в интерпретаторе: сам специализированный пакет профилирования определён в PEP 799, а соседний с ним безопасный внешний интерфейс отладчика описан в PEP 768, и документация прямо рекомендует его для отладки продакшена из-за минимальной цены наблюдения, в отличие от tracing, оставленного для разработки и тестов. Граница между мирами стала официальной: детерминированные съёмки на стенде, семплирование на живых нагрузках.

Вытесняет ли встроенный новосёл py-spy, вопрос открытый. Стандартный семплер ловит стеки своего процесса, а py-spy цепляется к чужому PID без единой строчки в коде, рисует готовый флэймграф и смотрит в нативные кадры расширений, чего встроенный пока не обещает. Разумный расклад на сегодня: встроенный sampling для собственных сервисов, где в код уже и так заходит инструментация, py-spy для чужих процессов, контейнеров и случаев, когда менять ничего нельзя.

Частые ошибки при чтении профиля и честные микрозамеры

Первый по частоте промах это оптимизация мелочи. Сортировка по tottime подсветила функцию на трёх процентах времени, её переписали неделю и честно ускорили программу на те же три процента. Правило отсечения простое: в работу берут полосы шире пятнадцати-двадцати процентов, остальное существует как фон. Второй промах это замер в вакууме: функция, вытащенная из программы, работает на тёплом кэше процессора и маленьком наборе значений, в бенчмарке летает и в сервисе буксует, потому что там и входы больше, и память холоднее. Третий промах это вера в единичный прогон: один запуск ловит и цикл сборщика мусора, и фоновую запись лога, и соседний процесс на том же ядре.

Честный микрозамер выглядит скромно, но дисциплинирует:

import time

def measure_once():
    start = time.perf_counter()
    process_orders()
    return time.perf_counter() - start

runs = sorted(measure_once() for _ in range(7))
print("медиана из семи прогонов", runs[3])

Медиана из нескольких прогонов устойчивее среднего: случайный выброс в обе стороны от минимума сам себя вычёркивает. Уточнение напрашивается само: time.perf_counter показывает настенные часы со всем ожиданием, а time.process_time только работу процессора, и разница между ними подсказывает, не в сети ли сидит настоящая причина медлительности. Сравнивать имеет смысл только замеры, снятые одним и тем же способом на одной машине, иначе арифметика превращается в подгонку под желаемый ответ.

Методика локализации узкого места от замера до подтверждённой строки

Оптимизация превращается из искусства в ремесло, если держаться короткого цикла, где каждая итерация измерима:

1. Зафиксировать метрику, секунды отклика или время батча, и целевую цифру, до которой имеет смысл работать;
2. Снять семплирующий профиль на реалистичной нагрузке, py-spy или встроенный sampling, и найти самые широкие полосы;
3. Уточнить картину на стенде через cProfile со сортировкой по tottime и связать подозреваемую строку со счётчиком вызовов;
4. Сформулировать гипотезу одним предложением и проверить её точечным замером через time.perf_counter вокруг подозрительного участка;
5. Изменить ровно одно место, прогнать ту же нагрузку и сравнить цифры до и после, а не ощущения до и после;
6. Остановиться при достижении цели, записать результат в задачу трекера и оставить нагрузочный тест в репозитории как страховку от откатов.

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

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