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

Модуль 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 -k 1 ./julia /test/fastmath.jl
$ perf inject --jit --input /tmp/perf.data --output /tmp/perf-jit.data
$ perf report --call-graph -G -i /tmp/perf-jit.data

Существует много других интересных вещей, которые вы можете измерить в вашей программе, чтобы получить полный список, пожалуйста, прочитайте страницу примеров Linux perf на http://www.brendangregg.com/perf.html.

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

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