Предположим, ваша 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-запросы могут оказаться более медленными, чем обычно. Иногда медленнее, чем обычно, могут загружаться какие-то данные. Поэтому полезно было бы использовать некие более предсказуемые показатели, которые не привязаны к скорости работы того, что окружает программу.
Один из способов это сделать заключается в подсчёте того, сколько операций, требующих ожидания, выполнил процесс. То есть — речь идёт о подсчёте количества периодов ожидания, а не времени, которое потрачено на ожидание чего-либо.
Процесс может прекратить пользоваться ресурсами процессора по двум причинам:
- Каждый раз, когда процесс выполняет операцию, которая не завершается мгновенно, например — читает данные из сокета, приостанавливает работу, и так далее, это равносильно тому, что он говорит операционной системе: «Разбуди меня тогда, когда я смогу продолжить работу». Это — так называемое «преднамеренное переключение контекста»: процессор может переключиться на выполнение другого процесса до тех пор, пока в сокете не появятся данные, или до тех пор, пока наш процесс не выйдет из режима ожидания, а также — в других подобных случаях.
- «Непреднамеренное переключение контекста» — это ситуация, в которой операционная система временно останавливает процесс, давая возможность другому процессу воспользоваться ресурсами процессора.
Мы будем профилировать преднамеренные переключения контекста.
Напишем профилировщик, который подсчитывает преднамеренные переключения контекста с использованием библиотеки 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-приложения?
Автор: ru_vds
