Профилировщики

Каталог землетрясений M5+ за 2015–2025 годы — 19 073 толчка. Отчёт ищет среди них сильнейшие, от M7, и для каждого считает, сколько толчков случилось за следующие 30 дней не дальше 300 километров. Код простой, но считается он заметно дольше, чем хотелось бы. Где теряется время? Напрашивается формула расстояния по сфере — в ней синусы, косинусы и арксинус. Ниже — что увидел профилировщик.

Формула расстояния — узкая полоска km, несколько процентов. Три четверти времени ушло в when: функцию, которая превращает строку «2025-07-29 23:24:50» в дату. Она вызывается при каждом сравнении во внутреннем цикле и разбирает одни и те же строки снова и снова — 52 194 раза на 153 сильных землетрясения. Внутри неё видно и то, чего никто не ждёт: strptime при каждом вызове проверяет, не сменилась ли в программе локаль. Переключите на «даты один раз»: даты разобраны при чтении, и отчёт стал в несколько раз быстрее. Теперь самое широкое — чтение CSV, и следующее ускорение искать надо там.

Идея

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

Граф пламени рисует эти цепочки. Каждый прямоугольник — функция, под ней — те, кого она вызвала, ширина — доля проб, в которых она была в стеке. Порядок слева направо ничего не значит, цвет здесь только различает свой код, библиотеки и среду выполнения. Смотреть нужно на широкие прямоугольники, под которыми пусто или почти пусто: там программа работает сама, а не ждёт вызванных. Такие графы придумал Брендан Грегг в 2011 году, разбираясь с производительностью MySQL, и теперь их рисуют почти все профилировщики. В сцене корень сверху, как в инструментах браузера; у Грегга пламя растёт снизу вверх.

Два вида профилировщиков

Детерминированный записывает каждый вызов и каждый возврат. Так работает cProfile, встроенный в Python: python -m cProfile -s cumtime report.py напечатает для каждой функции, сколько раз её вызвали и сколько в ней прошло времени. Числа вызовов точные — на этом отчёте ровно 52 194 вызова strptime и полтора миллиона вызовов функций всего. Но плата — время: каждый вызов теперь стоит дороже, и этот отчёт под cProfile идёт в 2,8 раза дольше. Больше всего прибавляют функции, которые вызываются часто и работают мало, поэтому их доля в таком профиле завышена.

Выборочный не вмешивается в вызовы, а заглядывает снаружи. Для Python это py-spy, который читает память работающего процесса и даже не требует его перезапускать, или Scalene; для Go — встроенный runtime/pprof, который сто раз в секунду прерывает программу сигналом и записывает стек; для всего остального — perf в Linux и Instruments в macOS. Ошибка у выборки статистическая, и её можно оценить, об этом ниже.

Код

Отчёт в двух вариантах. Первый разбирает дату при каждом сравнении, второй — один раз, причём функцией fromisoformat, которая написана на C и разбирает только формат ISO. Результаты совпадают — это первое, что нужно проверить после любого ускорения.

А это выборочный профилировщик целиком. Второй поток каждые полмиллисекунды берёт стек главного потока через sys._current_frames() и считает цепочки. Два места в нём — результат настоящих замеров, а не теории. В виртуальной машине, где работает песочница, time.sleep на полмиллисекунды спит почти три, поэтому поток ждёт сам, отдавая GIL вызовом sleep(0). А главный поток, пока работает чистый Python, отдаёт GIL раз в 5 мс; чтобы пробы шли чаще, на время замера этот интервал уменьшается через sys.setswitchinterval.

Вывод от запуска к запуску немного меняется: это выборка. Но картина одна и та же: сотни проб внутри strptime и считаные — у fromisoformat, который на этих строках быстрее в сотню раз. В Go то же делает pprof: pprof.StartCPUProfile(file) в начале, StopCPUProfile() в конце, потом go tool pprof -http=:8080 cpu.out показывает в браузере и таблицу, и граф пламени. Для тестов хватает флага: go test -cpuprofile cpu.out. Граф Go в сцене снят именно так; программа, которая сама разбирает формат pprof, лежит рядом с замером.

Один отчёт, два профиля

Переключите сцену на Go. Отчёт там быстрее в десяток раз, и горит он в другом месте: разбор дат функцией time.Parse — около четверти времени, а половина уходит на чтение CSV в словари. Каждая строка каталога превращается в отображение «поле → строка», и в профиле видны выделение памяти (mallocgc) и сборка мусора. Исправление, которое ускорило Python в несколько раз, ускоряет Go меньше чем в полтора: здесь надо было бы читать CSV прямо в массивы чисел.

Вывод простой и неудобный: профиль относится к конкретной программе на конкретном языке и данных. Нельзя перенести совет «разбирайте даты один раз» из одного языка в другой и ждать того же выигрыша — профилировать нужно то, что работает.

Насколько верить профилю

Профиль из N проб оценивает долю функции так же, как опрос оценивает долю голосов. Если на функцию на самом деле уходит доля p времени, то её доля в пробах отклоняется от p в среднем на √(p(1 − p)/N). В профиле Python в сцене около 2700 проб, и для 75% на разбор дат ошибка — меньше процентного пункта. В профиле Go проб около тридцати, и четверть на time.Parse известна с точностью около ±8 пунктов. Мелкие полоски в несколько проб — шум; чтобы их разглядеть, нужен прогон подольше.

Прежде чем ускорять, полезно прикинуть, сколько это вообще может дать. Если функция занимает долю p времени и стала в s раз быстрее, вся программа ускорится в 1 / ((1 − p) + p/s) раз — это закон Амдала (1967). Даже если разбор дат, 75% времени, исчезнет совсем, программа станет быстрее не больше чем вчетверо. У нас вышло чуть больше, потому что быстрый вариант заодно вынес из цикла разбор координат. А если оптимизировать функцию с 5% времени, весь выигрыш — не больше 5%, сколько бы сил на неё ни ушло.

• Профилируйте на настоящих данных. На десяти строках вместо девятнадцати тысяч горячим окажется запуск интерпретатора и импорт модулей — это видно и в нашем профиле: первый вызов strptime импортирует модуль, тонкая полоска importlib.
• Различайте время процессора и ожидание. pprof считает только время на процессоре: программа, которая ждёт сеть, в нём выглядит пустой. Наш профилировщик на Python смотрит на часы, а не на процессор, и ожидание увидит.
• Мелкие функции исчезают. Компилятор Go встраивает короткие функции в вызывающие; pprof умеет показывать их отдельно, но не все инструменты так делают.
• Измерьте после. Профиль показывает, где искать, но ускорение подтверждает только честный замер — как его делать, рассказано в статье «Как честно измерить скорость».

Задачи

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