Производительность — это не только CPU: создание собственных профилировщиков для Python

Предположим, ваша Python-программа оказалась медленной, и вы выяснили, что это лишь отчасти обусловлено нехваткой процессорных ресурсов. Как выяснить то, какие части кода вынуждены ожидать чего-то такого, что не относится к CPU?



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

• Чего может ожидать программа?
• Профилировка использования ресурсов, не являющихся ресурсами CPU.
• Профилировка непреднамеренных переключений контекста.

Чего ожидает программа?

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

• Сетевые ресурсы. Сюда может входить ожидание завершения операций DNS-поиска, ожидание ответа некоего сетевого ресурса, ожидание завершения загрузки неких данных и так далее.
• Жёсткий диск. Чтение данных с жёсткого диска может занимать некоторое время. То же самое можно сказать и о записи на диск. Иногда операции чтения или записи выполняются лишь с использованием кэша, расположенного в оперативной памяти. При таком подходе всё происходит довольно-таки быстро. Но иногда, когда программа напрямую взаимодействует с диском, подобные операции оказываются достаточно медленными.
• Блокировки. Программа может ожидать снятия блокировки потока или процесса.
• Приостановка работы. Иногда программа может преднамеренно приостановить работу, например, делая паузу между попытками выполнить некое действие.

Как обнаружить те места программ, в которых происходит что-то такое, что плохо влияет на производительность?

Способ №1: анализ времени, в течение которого программа не пользуется процессором

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

Операционная система может сообщить нам о том, сколько именно процессорного времени использовала программа.

Представим, что мы профилируем однопоточную программу. Многопоточные программы сложнее профилировать, да и описывать этот процесс тоже непросто. Если программа выполнялась 9 секунд и при этом пользовалась процессором 7.5 секунд — это означает, что она потратила 1.5 секунды на ожидание.

Для начала создадим таймер, который будет измерять время ожидания:

import os

def not_cpu_time():
    times = os.times()
    return times.elapsed - (times.system + times.user)

Затем создадим профилировщик, который выполняет анализ этого времени:

import cProfile, pstats

def profile_not_cpu_time(f, *args, **kwargs):
    prof = cProfile.Profile(not_cpu_time)
    prof.runcall(f, *args, **kwargs)
    result = pstats.Stats(prof)
    result.sort_stats("time")
    result.print_stats()

После этого можно профилировать различные функции:

>>> profile_not_cpu_time(
...     lambda: urlopen("https://pythonspeed.com").read())

ncalls  tottime  percall  filename:lineno(function)
    3    0.050    0.017   _ssl._SSLSocket.read
    1    0.040    0.040   _socket.getaddrinfo
    1    0.020    0.020   _socket.socket.connect
    1    0.010    0.010   _ssl._SSLSocket.do_handshake
  342    0.010    0.000   find.str
  192    0.010    0.000   append.list

Полученные результаты позволяют сделать вывод о том, что большая часть времени потрачена на чтение данных из сокета, но некоторое время ушло на выполнение DNS-поиска (getaddrinfo), а также на выполнение TCP-рукопожатия (connect) и TLS/SSL-рукопожатия.

Так как мы позаботились о том, чтобы исследовать те периоды работы программы, в которые она не пользуется ресурсами процессора, мы знаем, что всё это — чистое время ожидания, то есть — время, когда программа не занята какими-либо вычислениями.

Почему тут присутствует время, записанное для str.find и list.append? При выполнении подобных операций программе нечего ждать, поэтому правдоподобно выглядит объяснение, в соответствии с которым мы имеем дело с ситуацией, когда не выполнялся весь процесс. Возможно — ожидая окончания выполнения какого-то другого процесса, или ожидая завершения загрузки данных в память из файла подкачки. Это указывает на то, что на выполнение данных операций было затрачено некоторое время, которое не входит в состав процессорного времени.

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

Способ №2: анализ количества преднамеренных переключений контекста

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

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

Процесс может прекратить пользоваться ресурсами процессора по двум причинам:

1. Каждый раз, когда процесс выполняет операцию, которая не завершается мгновенно, например — читает данные из сокета, приостанавливает работу, и так далее, это равносильно тому, что он говорит операционной системе: «Разбуди меня тогда, когда я смогу продолжить работу». Это — так называемое «преднамеренное переключение контекста»: процессор может переключиться на выполнение другого процесса до тех пор, пока в сокете не появятся данные, или до тех пор, пока наш процесс не выйдет из режима ожидания, а также — в других подобных случаях.
2. «Непреднамеренное переключение контекста» — это ситуация, в которой операционная система временно останавливает процесс, давая возможность другому процессу воспользоваться ресурсами процессора.

Мы будем профилировать преднамеренные переключения контекста.

Напишем профилировщик, который подсчитывает преднамеренные переключения контекста с использованием библиотеки psutil:

import psutil

_current_process = psutil.Process()

def profile_voluntary_switches(f, *args, **kwargs):
    prof = cProfile.Profile(
        lambda: _current_process.num_ctx_switches().voluntary)
    prof.runcall(f, *args, **kwargs)
    result = pstats.Stats(prof)
    result.sort_stats("time")
    result.print_stats()

Теперь снова проведём профилирование кода, который работает с сетью:

>>> profile_voluntary_switches(
...     lambda: urlopen("https://pythonspeed.com").read())

ncalls  tottime  percall  filename:lineno(function)
     3    7.000    2.333  _ssl._SSLSocket.read
     1    2.000    2.000  _ssl._SSLSocket.do_handshake
     1    2.000    2.000  _socket.getaddrinfo
     1    1.000    1.000  _ssl._SSLContext.set_default_verify_path
     1    1.000    1.000  _socket.socket.connect

Теперь, вместо данных о времени ожидания, мы можем видеть сведения о количестве произошедших преднамеренных переключений контекста.

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

Итоги

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

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

• Количество операций чтения (psutil.Process().read_count) и записи (psutil.Process().write_count).
• В Linux — общее число прочитанных и записанных байтов (psutil.Process().read_chars).
• Показатели выделения памяти (выполнение подобного анализа потребует определённых усилий, сделать это можно с помощью jemalloc).

Подробности по первым двум пунктам этого списка можно найти в документации по psutil.

Уважаемые читатели! Как вы профилируете свои Python-приложения?