Fast Python. В поисках медленного кода при помощи стандартного профайлера

Думаю все часто сталкивались с ситуацией, когда бизнес приходит и говорит: спасайте, страница Х нашего прекрасного веб-приложения работает медленно. Или, создание репортов стало занимать в два раза больше времени после последнего деплоя. И хорошо, когда ты наверняка знаешь в чем причина и спокойно переходишь к оптимизации медленного кода, но что делать, если ты не уверен, где проблема? Вот про это мы сегодня и поговрим: использование стандартного профайлера для поиска медленного кода.

Сразу оговорюсь, что есть намного более универсальные библиотеки для профайлинга Python приложений, как например, vprof или pyflame, но я хотел бы рассказать именно про cProfile.

Итак, что надо сделать, чтоб отпрофилировать наш код? На самом деле просто запомнить, как запускать профайлер:

$ python -m cProfile -o script.prof script.py

Ну а в Python 3.7 все стало еще приятней, потому что появилась возможность задавать -m для профайлера как:

$ python -m cProfile -o project.prof -m project

После того как скрипт выполнится, мы получим script.prof файл, который теперь можно эксплорить при помощи KCacheGrind. Для этого нужно перевести его в формат, который понимает KCacheGrind, что делает тулза под названием: pyprof2calltree.

$ pyprof2calltree -i script.prof -k

переконвертирует script.prof в дерево вызовов и откроет приятный глазу интерфейс KCacheGrind.

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

1. В начале project/__main__.py создаю профайлер и запускаю его, если в окружении есть переменная USE_PROFILER
2. Оборачиваю web.run_app(...) в try/finally и в finally печатаю содержимое профайлера в файл
3. Потом запускаю приложение как USE_PROFILER=1 python -m project
4. И наконец делаю нагрузку на необходимый URL при помощи wrk, например как, wrk -t 4 -c 100 -d 30s --latency http://<URL>/api/slow
5. Все теперь можно выключать приложение и запускать KCacheGrind

Если теперь перевести это все на код, то получится вот такой апдейт для project/__main__.py,

import cProfile
import os

from app import create_app


USE_PROFILER = os.environ.get('USE_PROFILER') == '1'
profiler = cProfiler.Profile()


if __name__ == '__main__':
    if USE_PROFILER:
        profiler.enable()

    try:
        sys.exit(web.run_app(create_app()))
    finally:
        if USE_PROFILER:
            filename = 'project.prof'
            print(f'Dumping profiler to {filename}')
            profiler.dump_stats(filename)
            profiler.disable()

В итоге, в KCacheGrind, находим интересующую вьюху (на моем скриншоте это retrieve_tweets) и ищем почему же она работает медленно.

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