Профилирование

Поработаем с простым тестовым примером:

Сначала следует запустить код, который вы собираетесь профилировать, хотя бы один раз (если только вы не будете профилировать JIT-компилятор Julia):

Теперь все готово для профилирования этой функции:

Для просмотра результатов профилирования существует несколько графических браузеров. Одно «семейство» визуализаторов основано на FlameGraphs.jl, при этом каждый член семейства предоставляет свой пользовательский интерфейс:

Полностью независимым подходом к визуализации профилирования является PProf.jl, который использует внешний инструмент pprof.

Однако здесь мы будем использовать текстовое отображение, которое входит в состав стандартной библиотеки:

Каждая строка здесь представляет определенное место (номер строки) в коде. Отступы используются для указания вложенной последовательности вызовов функций, при этом строки с большим отступом располагаются глубже в последовательности вызовов. В каждой строке первое «поле» — это количество обратных трассировок (выборок), выполненных в этой строке или любых функциях, выполняемых этой строкой. Второе поле — это имя файла и номер строки, третье поле — это имя функции. Обратите внимание, что конкретные номера строк могут меняться по мере изменения кода Julia. Если вы хотите отследить этот момент, лучше запустить этот пример самостоятельно.

В этом примере мы видим, что вызываемая функция верхнего уровня находится в файле event.jl. Это функция, которая запускает REPL при запуске Julia. Если взглянуть на строку 97 файла REPL.jl, вы увидите, что здесь вызывается функция eval_user_input(). Эта функция обрабатывает ваш ввод в REPL, и поскольку мы работаем в интерактивном режиме, эти функции были вызваны, когда мы ввели @profile myfunc(). Следующая строка отражает действия, выполненные в макросе @profile.

Первая строка показывает, что 80 обратных трассировок были выполнены в строке 73 файла event.jl, но дело не в том, что эта строка была «дорогой» сама по себе: третья строка показывает, что все 80 обратных трассировок были фактически запущены внутри ее вызова eval_user_input, и так далее. Чтобы выяснить, на какие операции действительно уходит время, нужно заглянуть глубже в цепочку вызовов.

Вот первая важная строка в этом выводе:

REPL относится к тому факту, что мы определили функцию (myfunc) в REPL, а не поместили ее в файл. Если бы мы использовали файл, здесь бы отображалось его имя. [1] показывает, что функция (myfunc) была первым выражением, вычисленным в этом сеансе REPL. Строка 2 функции (myfunc()) содержит вызов rand, и в ней произошло 52 (из 80) обратных трассировки. Ниже вы можете увидеть вызов функции dsfmt_fill_array_close_open! внутри файла dSFMT.jl.

Чуть дальше вы видите:

Строка 3 функции (myfunc) содержит вызов maximum, и в ней произошло 28 (из 80) обратных трассировок. Ниже вы можете увидеть конкретные места в файле base/reduce.jl, в которых выполняются трудоемкие операции в функции maximum для данного типа входных данных.

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

В общем, при наличии N выборок, собранных в одной строке, можно ожидать неопределенность в отношении порядка sqrt(N) (если не учитывать другие источники шума, например загруженность компьютера другими задачами). Основным исключением из этого правила является сборка мусора, которая выполняется нечасто, но, как правило, является довольно дорогостоящей. (Поскольку сборщик мусора в Julia написан на языке C, такие события можно обнаружить с помощью режима вывода C=true, описанного ниже, или с помощью ProfileView.jl.)

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

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

Если бы вы профилировали dumbsum3 и во время выполнения dumbsum(1) осуществили обратную трассировку, она выглядела бы следующим образом:

Следовательно, эта дочерняя функция получает три вычисления, хотя родительская получает только одно. Представление в виде дерева делает эту ситуацию гораздо более понятной, и по этой причине (среди прочих), вероятно, является наиболее предпочтительным способом просмотра результатов.

Результаты макроса @profile накапливаются в буфере. Если вы выполняете несколько фрагментов кода с помощью макроса @profile, то Profile.print() выведет объединенные результаты. Это может быть очень полезно. Но иногда хочется начать с чистого листа, и это можно сделать с помощью функции Profile.clear().

Profile.print имеет и другие параметры, которые мы еще не рассматривали. Вот полное объявление:

Сначала обсудим два позиционных аргумента, а затем — именованные аргументы.

Возможно любое сочетание следующих именованных аргументов:

Имена файлов или функций иногда усекаются (с помощью ...), а отступы усекаются с помощью +n в начале, где n — это количество дополнительных пробелов, которые были бы вставлены, если для них было бы место. Если вам нужен полный профиль глубоко вложенного кода, часто рекомендуется сохранять его файл с использованием широкого displaysize в IOContext:

@profile просто накапливает обратные трассировки, а анализ происходит, когда вы вызываете Profile.print(). При длительном вычислении вполне возможно, что предварительно выделенный буфер для хранения обратных трассировок будет заполнен. Если это произойдет, обратные трассировки остановятся, но вычисления продолжатся. В результате некоторые важные данные профилирования могут отсутствовать (в этом случае будет выведено предупреждение).

Вы можете получить и настроить соответствующие параметры следующим образом:

n — это общее количество указателей инструкций, доступное для хранения. Значение по умолчанию — 10^6. Если стандартная обратная трассировка состоит из 20 указателей инструкций, вы можете собрать 50 000 обратных трассировок, что предполагает статистическую погрешность менее 1 %. Этого может быть достаточно для большинства приложений.

Следовательно, скорее всего, вам потребуется изменить задержку (delay), выраженную в секундах, которая задает количество времени, доступное в Julia между моментальными снимками для выполнения требуемых вычислений. Для весьма продолжительного задания могут не требоваться частые обратные трассировки. Параметр по умолчанию — delay = 0.001. Конечно, задержку можно как уменьшить, так и увеличить. Однако затраты на профилирование возрастают, когда задержка становится аналогичной времени, необходимому для создания обратной трассировки (~30 микросекунд на ноутбуке автора).

Одним из наиболее распространенных методов повышения производительности является уменьшение объема выделяемой памяти. В Julia доступно несколько инструментов для измерения:

Сейчас Julia поддерживает Intel VTune, OProfile и perf в качестве инструментов внешнего профилирования.

В зависимости от выбранного инструмента выполняйте компиляцию с помощью переменных USE_INTEL_JITEVENTS, USE_OPROFILE_JITEVENTS и USE_PERF_JITEVENTS, которым задано значение 1 в Make.user. Поддерживается несколько флагов.

Перед запуском Julia задайте переменной среды ENABLE_JITPROFILING значение 1.

Теперь вы можете использовать эти инструменты различными способами. Например, с помощью OProfile вы можете попробовать простую запись:

Или это можно сделать с помощью perf:

Существует еще множество других интересных вещей, которые вы можете измерить в вашей программе. Полный список можно найти на странице примеров Linux perf.

Помните, что perf сохраняет для каждого выполнения файл perf.data, который даже для небольших программ может стать довольно объемным. Кроме того, модуль perf LLVM сохраняет временные объекты отладки в папку ~/.debug/jit. Не забывайте регулярно очищать ее.