Хабрахабр

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

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

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

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

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

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

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

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

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

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

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

Многопоточные программы сложнее профилировать, да и описывать этот процесс тоже непросто. Представим, что мы профилируем однопоточную программу. 5 секунд — это означает, что она потратила 1. Если программа выполнялась 9 секунд и при этом пользовалась процессором 7. 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-приложения?

Теги
Показать больше

Похожие статьи

Добавить комментарий

Ваш e-mail не будет опубликован. Обязательные поля помечены *

Кнопка «Наверх»
Закрыть