Профилирование Python: cProfile, line_profiler и поиск узкого места

Скрипт, который парсит выгрузку и складывает результат в базу, работает 40 секунд на 10 000 строк. Ускорять наугад — переписать сериализацию, добавить кеш, поменять цикл на генератор — можно неделю и без результата. Профилировщик отвечает на один вопрос: куда именно уходит время. В стандартной библиотеке для этого есть cProfile, для построчного разбора горячей функции — сторонний line_profiler. Ниже — как ими пользоваться на CPython 3.11–3.13, что каждый показывает и где показания обманывают.

Первый замер: cProfile на всю программу

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

python -m cProfile -s cumtime myscript.py

Флаг -s cumtime сортирует по совокупному времени (функция плюс всё, что она вызвала). Первые строки вывода — самые тяжёлые ветки. Второй важный ключ сортировки — tottime: время внутри самой функции без вложенных вызовов. Разница между ними и есть подсказка.

Высокий cumtime и низкий tottime — функция сама почти ничего не делает, время утекает в то, что она зовёт. Копайте глубже. Высокий tottime — узкое место найдено, оптимизируйте её тело.

Профилирование куска, а не всего файла

Гонять весь скрипт под профилировщиком дорого и шумно: замусоривается импортами и инициализацией. Оберните подозрительный участок вручную:

import cProfile
import pstats

def process_records(records):
    result = []
    for row in records:
        result.append(transform(row))
    return result

profiler = cProfile.Profile()
profiler.enable()

process_records(load_records())

profiler.disable()

# Печатаем 15 самых тяжёлых функций по времени внутри них
stats = pstats.Stats(profiler)
stats.sort_stats('tottime')
stats.print_stats(15)

Вывод pstats состоит из колонок: ncalls — число вызовов, tottime — суммарное время внутри функции, percall рядом с ним — на один вызов, cumtime — совокупное. Смотрите на строки, где либо огромный tottime, либо огромный ncalls при заметном percall.

Как читать результат

• Миллионы вызовов дешёвой функции. Часто виноват не сам код, а то, что его зовут в цикле лишний раз. Пример: len() внутри условия цикла или обращение к свойству, которое пересчитывается каждый раз.
• Одна функция с гигантским tottime. Здесь и нужен построчный разбор — переходите к line_profiler.
• Время в методах драйвера БД или requests. Узкое место не в Python, а в сети или диске. Профилировщик CPU тут покажет ожидание как время — об этом отдельно ниже.

line_profiler: спускаемся до строки

cProfile показывает функцию, но не говорит, какая строка внутри неё жрёт время. Для этого есть line_profiler — сторонний пакет, ставится отдельно:

pip install line_profiler

Работает он избирательно: измеряет только функции, помеченные декоратором @profile. Декоратор не нужно импортировать — его внедряет утилита запуска kernprof. Помечаете горячую функцию, найденную через cProfile:

# myscript.py
@profile
def transform(row):
    parsed = row.strip().split(';')
    normalized = [x.lower() for x in parsed]
    key = '|'.join(normalized)
    return {'key': key, 'raw': row}

Запуск и просмотр отчёта — две команды:

kernprof -l -v myscript.py

Флаг -l включает построчный режим, -v сразу печатает отчёт после выполнения. Вывод показывает по каждой строке: сколько раз она выполнилась (Hits), суммарное время (Time), время на попадание (Per Hit) и долю от общего времени функции (% Time). Последняя колонка — то, ради чего всё затевалось: она прямо указывает виноватую строку.

Если запускаете под IPython или Jupyter, вместо декоратора и kernprof доступна magic-команда %lprun после загрузки расширения %load_ext line_profiler — точный синтаксис смотрите в документации пакета, он зависит от версии.

Где искать узкое место: карта решений

Инструмент выбирается по тому, что уже известно о проблеме. Ошибка новичка — сразу лезть в line_profiler, не сделав общий замер, и профилировать не ту функцию.

Детерминированный против сэмплирующего

cProfile и line_profiler — детерминированные: они фиксируют каждый вызов и каждую строку. Точно, но с накладными расходами, которые искажают картину для очень частых мелких вызовов. Сэмплирующие профилировщики вроде py-spy периодически снимают стек и не трогают код программы — их запускают на боевом процессе по PID. Для прода это единственный безопасный вариант: детерминированный профайлер под нагрузкой замедлит сервис в разы.

Где показания обманывают

Профилировщик — не истина в последней инстанции. Три случая, когда цифры вводят в заблуждение:

1. Оверхед на дешёвые вызовы. cProfile добавляет время на каждый вход и выход из функции. Для миллиона вызовов простой функции этот оверхед сопоставим с полезной работой, и функция кажется тяжелее, чем в реальном запуске без профайлера. Проверяйте выводы обычным timeit на изолированном куске.
2. Ожидание ввода-вывода выглядит как работа. Если функция ждёт ответ базы или HTTP, её cumtime будет большим, но CPU при этом простаивает. Оптимизировать Python-код тут бесполезно — время уходит в сеть или диск. Смотрите на разницу между wall-time и CPU-time.
3. C-расширения непрозрачны. Время внутри numpy, pandas или скомпилированных модулей cProfile покажет как один вызов без детализации. line_profiler туда тоже не заглянет — измерить построчно можно только чистый Python.

Что такое wall-time и CPU-time

Wall-time — время по настенным часам, сколько прошло реально. CPU-time — сколько процессор был занят вычислениями. Если wall-time сильно больше CPU-time, программа чего-то ждёт: сети, диска, блокировки. Профилировщик CPU в этом случае бесполезен.

Что делать дальше

После того как строка найдена и исправлена, повторите замер тем же способом и на тех же данных — оптимизация без контрольного прогона это вера, а не инженерия. Дальше по ситуации: если узкое место в частых мелких вызовах, смотрите в сторону векторизации через numpy или кеширования результатов; если в ожидании БД — в сторону пакетных запросов и индексов, а не Python; если в памяти — подключайте tracemalloc из стандартной библиотеки, у него своя логика снимков и сравнения. Для непрерывного профилирования боевого сервиса разверните py-spy и снимайте flame graph под реальной нагрузкой — синтетические данные часто прячут настоящее узкое место.