Profiling

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

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

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

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

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

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

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

Basic usage

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

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, при этом каждый член семьи предоставляет различный пользовательский интерфейс:

• VS Code является полноценной средой разработки с встроенной поддержкой визуализации профилей.
• ProfileView.jl является автономным визуализатором на основе GTK
• ProfileVega.jl использует VegaLight и хорошо интегрируется с Jupyter ноутбуками
• StatProfilerHTML.jl генерирует HTML и предоставляет некоторые дополнительные резюме, а также хорошо интегрируется с Jupyter notebooks
• ProfileSVG.jl отображает SVG
• PProf.jl служит локальным веб-сайтом для инспекции графиков, флеймграфиков и многого другого
• ProfileCanvas.jl является интерфейсом просмотра профиля на основе HTML canvas, используемым Julia VS Code extension, но также может генерировать интерактивные HTML файлы.

Совершенно независимый подход к визуализации профилей — это 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 счета, хотя родитель получает только один. Представление в виде "дерева" делает это гораздо яснее, и по этой причине (среди прочего) это, вероятно, самый полезный способ просмотра результатов.

Accumulation and clearing

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

Options for controlling the display of profile results

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

Configuration

@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 микросекунд на ноутбуке автора).

Memory allocation analysis

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

@time

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

GC Logging

В то время как @time регистрирует высокоуровневую статистику об использовании памяти и сборке мусора в процессе оценки выражения, может быть полезно регистрировать каждое событие сборки мусора, чтобы получить интуитивное представление о том, как часто работает сборщик мусора, как долго он работает каждый раз и сколько мусора он собирает каждый раз. Это можно включить с помощью GC.enable_logging(true), что заставляет Julia регистрировать в stderr каждый раз, когда происходит сборка мусора.

Allocation Profiler

Профайлер распределения записывает трассировку стека, тип и размер каждого распределения во время его работы. Его можно вызвать с помощью Profile.Allocs.@profile.

Эта информация об аллокациях возвращается в виде массива объектов Alloc, обернутых в объект AllocResults. Наилучший способ визуализировать их в настоящее время - с помощью пакетов PProf.jl и ProfileCanvas.jl, которые могут визуализировать стеки вызовов, производящие наибольшее количество аллокаций.

Профайлер распределения действительно имеет значительные накладные расходы, поэтому можно передать аргумент sample_rate, чтобы ускорить его, заставив пропускать некоторые распределения. Передача sample_rate=1.0 заставит его записывать все (что медленно); sample_rate=0.1 будет записывать только 10% распределений (быстрее) и т. д.

Для получения дополнительной информации о том, как использовать этот инструмент, пожалуйста, посмотрите следующий доклад с JuliaCon 2022: https://www.youtube.com/watch?v=BFvpwC8hEWQ

Allocation Profiler Example

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

using Profile, PProf
Profile.Allocs.clear()
Profile.Allocs.@profile sample_rate=0.0001 my_function()
PProf.Allocs.pprof()

Вот более подробный пример, показывающий, как мы можем настроить частоту выборки. Хорошее количество образцов, на которое стоит ориентироваться, составляет около 1 - 10 тысяч. Слишком много, и визуализатор профиля может быть перегружен, а профилирование будет медленным. Слишком мало, и у вас не будет репрезентативной выборки.

julia> import Profile

julia> @time my_function()  # Estimate allocations from a (second-run) of the function
  0.110018 seconds (1.50 M allocations: 58.725 MiB, 17.17% gc time)
500000

julia> Profile.Allocs.clear()

julia> Profile.Allocs.@profile sample_rate=0.001 begin   # 1.5 M * 0.001 = ~1.5K allocs.
           my_function()
       end
500000

julia> prof = Profile.Allocs.fetch();  # If you want, you can also manually inspect the results.

julia> length(prof.allocs)  # Confirm we have expected number of allocations.
1515

julia> using PProf  # Now, visualize with an external tool, like PProf or ProfileCanvas.

julia> PProf.Allocs.pprof(prof; from_c=false)  # You can optionally pass in a previously fetched profile result.
Analyzing 1515 allocation samples... 100%|████████████████████████████████| Time: 0:00:00
Main binary filename not available.
Serving web UI on http://localhost:62261
"alloc-profile.pb.gz"

Затем вы можете просмотреть профиль, перейдя по адресу http://localhost:62261, и профиль сохранен на диск. См. пакет PProf для получения дополнительных опций.

Allocation Profiling Tips

Как указано выше, стремитесь к примерно 1-10 тысячам образцов в вашем профиле.

Обратите внимание, что мы равномерно выбираем образцы в пространстве всех распределений и не взвешиваем наши образцы по размеру распределения. Таким образом, данная профилировка распределения может не давать представительного профиля того, где большинство байтов выделяется в вашей программе, если вы не установили sample_rate=1.

Аллокации могут происходить от пользователей, непосредственно создающих объекты, но также могут происходить изнутри среды выполнения или быть вставлены в скомпилированный код для обработки нестабильности типов. Просмотр "исходного кода" может быть полезен для их изоляции, а затем другие внешние инструменты, такие как Cthulhu.jl, могут быть полезны для определения причины аллокации.

Allocation Profile Visualization Tools

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

• PProf.jl

• ProfileCanvas.jl

• Встроенный визуализатор профилей VSCode (@profview_allocs) [документация необходима]

• Просмотр результатов непосредственно в REPL

  • Вы можете просмотреть результаты в REPL через Profile.Allocs.fetch(), чтобы увидеть трассировку стека и тип каждого выделения.

Line-by-Line Allocation Tracking

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

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

External Profiling

В настоящее время 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 examples page.

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