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

Модуль 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()

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

Juno — это полная интегрированная среда разработки с встроенной поддержкой визуализации профилей.
ProfileView.jl — автономный визуализатор, основанный на GTK.
ProfileVega.jl использует VegaLight и хорошо интегрируется с Jupyter-тетрадками.
StatProfilerHTML генерирует HTML и предоставляет некоторые дополнительные сводки, а также хорошо интегрируется с Jupyter-тетрадками.
ProfileSVG отображает SVG.

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

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 examples.

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

© 2009–2020 Jeff Bezanson, Stefan Karpinski, Viral B. Shah, and other contributors
Licensed under the MIT License.
https://docs.julialang.org/en/v1.5.3/manual/profile/