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

Модуль Profile предоставляет инструменты для помощи разработчикам в улучшении производительности их кода. При использовании он производит измерения выполняемого кода и генерирует вывод, который помогает понять, сколько времени тратится на отдельные строки. Наиболее распространённое использование — выявление «узких мест» для оптимизации.

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

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

Профайлер выборочного типа не обеспечивает полного покрытия по строкам, поскольку трассировки стека происходят через определённые интервалы (по умолчанию 1 мс на системах Unix и 10 мс на Windows, хотя фактическое планирование зависит от нагрузки операционной системы). Кроме того, как обсуждается далее, поскольку выборки собираются в редких точках всего выполнения, данные, собранные выборочным профайлером, подвержены статистическому шуму.

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

• Вам не нужно вносить какие-либо изменения в свой код для проведения измерений времени (в отличие от альтернативного инструментирующего профайлера).
• Он может профилировать код ядра Julia и даже (по желанию) библиотеки C и Fortran.
• Благодаря «редкому» запуску, накладные расходы на производительность очень невелики; во время профилирования ваш код может выполняться практически с родной скоростью.

По этим причинам рекомендуется попробовать использовать встроенный выборочный профайлер перед рассмотрением альтернатив.

Основное использование

Давайте поработаем с простым тестовым случаем:

julia> function myfunc()
           A = rand(200, 200, 400)
           maximum(A)
       end

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

julia> myfunc() # run once to force compilation

Теперь мы готовы профилировать эту функцию:

julia> using Profile

julia> @profile myfunc()

Чтобы увидеть результаты профилирования, доступен графический браузер, но здесь мы будем использовать текстовый вывод, который входит в стандартную библиотеку:

julia> Profile.print()
80 ./event.jl:73; (::Base.REPL.##1#2{Base.REPL.REPLBackend})()
 80 ./REPL.jl:97; macro expansion
  80 ./REPL.jl:66; eval_user_input(::Any, ::Base.REPL.REPLBackend)
   80 ./boot.jl:235; eval(::Module, ::Any)
    80 ./<missing>:?; anonymous
     80 ./profile.jl:23; macro expansion
      52 ./REPL[1]:2; myfunc()
       38 ./random.jl:431; rand!(::MersenneTwister, ::Array{Float64,3}, ::Int64, ::Type{B...
        38 ./dSFMT.jl:84; dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_state, ::Ptr{F...
       14 ./random.jl:278; rand
        14 ./random.jl:277; rand
         14 ./random.jl:366; rand
          14 ./random.jl:369; rand
      28 ./REPL[1]:3; myfunc()
       28 ./reduce.jl:270; _mapreduce(::Base.#identity, ::Base.#scalarmax, ::IndexLinear,...
        3  ./reduce.jl:426; mapreduce_impl(::Base.#identity, ::Base.#scalarmax, ::Array{F...
        25 ./reduce.jl:428; mapreduce_impl(::Base.#identity, ::Base.#scalarmax, ::Array{F...

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

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

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

Первая «важная» строка в этом выводе выглядит так:

52 ./REPL[1]:2; myfunc()

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

Немного ниже вы видите:

28 ./REPL[1]:3; myfunc()

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

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

julia> @profile (for i = 1:100; myfunc(); end)

julia> Profile.print()
[....]
 3821 ./REPL[1]:2; myfunc()
  3511 ./random.jl:431; rand!(::MersenneTwister, ::Array{Float64,3}, ::Int64, ::Type...
   3511 ./dSFMT.jl:84; dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_state, ::Ptr...
  310  ./random.jl:278; rand
   [....]
 2893 ./REPL[1]:3; myfunc()
  2893 ./reduce.jl:270; _mapreduce(::Base.#identity, ::Base.#scalarmax, ::IndexLinea...
   [....]

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

Это демонстрирует стандартный «деревовидный» вывод; альтернативой является «плоский» вывод, который накапливает счётчики независимо от их вложенности:

julia> Profile.print(format=:flat)
 Count File          Line Function
  6714 ./<missing>     -1 anonymous
  6714 ./REPL.jl       66 eval_user_input(::Any, ::Base.REPL.REPLBackend)
  6714 ./REPL.jl       97 macro expansion
  3821 ./REPL[1]        2 myfunc()
  2893 ./REPL[1]        3 myfunc()
  6714 ./REPL[7]        1 macro expansion
  6714 ./boot.jl      235 eval(::Module, ::Any)
  3511 ./dSFMT.jl      84 dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_s...
  6714 ./event.jl      73 (::Base.REPL.##1#2{Base.REPL.REPLBackend})()
  6714 ./profile.jl    23 macro expansion
  3511 ./random.jl    431 rand!(::MersenneTwister, ::Array{Float64,3}, ::In...
   310 ./random.jl    277 rand
   310 ./random.jl    278 rand
   310 ./random.jl    366 rand
   310 ./random.jl    369 rand
  2893 ./reduce.jl    270 _mapreduce(::Base.#identity, ::Base.#scalarmax, :...
     5 ./reduce.jl    420 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
   253 ./reduce.jl    426 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
  2592 ./reduce.jl    428 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
    43 ./reduce.jl    429 mapreduce_impl(::Base.#identity, ::Base.#scalarma...

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

dumbsum(n::Integer) = n == 1 ? 1 : 1 + dumbsum(n-1)
dumbsum3() = dumbsum(3)

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

dumbsum3
    dumbsum(3)
        dumbsum(2)
            dumbsum(1)

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

Накопление и очистка

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

Параметры управления отображением результатов профилирования

Profile.print имеет больше параметров, чем мы описали до сих пор. Давайте посмотрим на полное объявление:

function print(io::IO = stdout, data = fetch(); kwargs...)

Давайте сначала обсудим два позиционных аргумента, а затем ключевые аргументы:

• io — позволяет сохранить результаты в буфере, например, в файле, но по умолчанию вывод происходит в stdout (консоль).

• data — содержит данные, которые вы хотите проанализировать; по умолчанию они получаются из Profile.fetch(), который извлекает трассировки стека из предварительно выделенного буфера. Например, если вы хотите профилировать профайлер, вы можете сказать:

  data = copy(Profile.fetch())
  Profile.clear()
  @profile Profile.print(stdout, data) # Prints the previous results
  Profile.print()                      # Prints results from Profile.print()

Ключевые аргументы могут быть любой комбинацией:

• format — введённый выше, определяет, выводятся ли трассировки стека с (по умолчанию, :tree) или без (:flat) отступов, указывающих структуру дерева.
• C — Если true, трассировки стека из кода C и Fortran отображаются (обычно они исключаются). Попробуйте запустить начальный пример с Profile.print(C = true). Это может быть очень полезно для определения, код Julia или C вызывает узкое место; установка C = true также улучшает интерпретируемость вложенности, за счёт более длинных выводов профиля.
• combine — Некоторые строки кода содержат несколько операций; например, s += A[i] содержит как обращение к массиву (A[i]), так и операцию суммирования. Эти операции соответствуют разным строкам в сгенерированном машинном коде, и поэтому во время трассировок стека может быть захвачено два или более разных указателя адреса. combine = true объединяет их, и это, вероятно, то, что вам обычно нужно, но вы можете сгенерировать отдельный вывод для каждого уникального указателя инструкции с combine = false.
• maxdepth — Ограничивает кадры на глубине, превышающей maxdepth в формате :tree.
• sortedby — Управляет порядком в формате :flat . :filefuncline (по умолчанию) сортирует по строке исходного кода, а :count сортирует в порядке количества собранных выборок.
• noisefloor — Ограничивает кадры, которые находятся ниже эвристической пороговой величины шума выборки (применимо только к формату :tree). Рекомендуемое значение для пробы — 2.0 (по умолчанию 0). Этот параметр скрывает выборки, для которых n <= noisefloor * √N, где n — количество выборок в этой строке, а N — количество выборок для вызываемой функции.
• mincount — Ограничивает кадры с менее чем mincount случаями.

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

open("/tmp/prof.txt", "w") do s
    Profile.print(IOContext(s, :displaysize => (24, 500)))
end

Настройка

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

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

Profile.init() # returns the current settings
Profile.init(n = 10^7, delay = 0.01)

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

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

Анализ распределения памяти

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

Чтобы измерить распределение по строкам, запустите Julia с параметром командной строки --track-allocation=<setting>, для которого можно выбрать none (по умолчанию, не измерять распределение), user (измерять распределение памяти везде, кроме ядра Julia), или all (измерять распределение памяти в каждой строке кода Julia). Распределение измеряется для каждой строки скомпилированного кода. При выходе из Julia кумулятивные результаты записываются в текстовые файлы с .mem, добавленным после имени файла, в той же директории, что и исходный файл. Каждая строка содержит общее количество распределённых байт. Coverage пакет содержит некоторые базовые инструменты анализа, например, для сортировки строк по количеству распределённых байтов.

При интерпретации результатов есть несколько важных деталей. В режиме user первая строка любой функции, вызываемой непосредственно из REPL, покажет распределение из-за событий, происходящих в самом коде REPL. Более существенно, что JIT-компиляция также добавляет к счётчикам распределения, поскольку значительная часть компилятора Julia написана на Julia (и компиляция обычно требует распределения памяти). Рекомендуемая процедура заключается в принудительной компиляции, выполнив все команды, которые вы хотите проанализировать, а затем вызвав Profile.clear_malloc_data() для сброса всех счётчиков распределения. Затем выполните необходимые команды и выйдите из Julia, чтобы инициировать создание файлов .mem.

Внешнее профилирование

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

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

Перед запуском Julia установите переменную окружения ENABLE_JITPROFILING в значение 1.

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

>ENABLE_JITPROFILING=1 sudo operf -Vdebug ./julia test/fastmath.jl
>opreport -l `which ./julia`

Или аналогично с perf:

$ ENABLE_JITPROFILING=1 perf record -o /tmp/perf.data --call-graph dwarf ./julia /test/fastmath.jl
$ perf report --call-graph -G

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

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