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

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

• VS Code — это полная IDE с встроенной поддержкой визуализации профилей
• ProfileView.jl — автономный визуализатор, основанный на GTK
• ProfileVega.jl использует VegaLight и хорошо интегрируется с Jupyter-тетрадями
• StatProfilerHTML.jl генерирует HTML и предоставляет дополнительные сводки, а также хорошо интегрируется с Jupyter-тетрадями
• ProfileSVG.jl отображает SVG
• PProf.jl предоставляет локальный веб-сайт для проверки графиков, диаграмм пламени и не только
• ProfileCanvas.jl — визуализатор профилей на основе HTML-холста, используемый расширением Julia VS Code, но также может генерировать интерактивные 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 счётчика, даже если родительская функция получает только один. Представление «дерево» делает это гораздо яснее, и по этой причине (среди прочих) является, вероятно, наиболее полезным способом просмотра результатов.

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

Результаты от @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 occurrences.

Имена файлов/функций иногда усекаются (с ...), а отступы усекаются с +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 микросекунд на ноутбуке автора).

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

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

@time

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

Журналирование GC

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

Профилировщик распределения

Профилировщик распределения записывает трассировку стека, тип и размер каждого выделения во время его работы. Его можно вызвать с помощью 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

Пример профилировщика распределения

В этом простом примере мы используем 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 для дополнительных опций.

Рекомендации по профилированию распределения

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

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

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

Инструменты визуализации профилей распределения

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

• PProf.jl
• ProfileCanvas.jl
• Встроенный визуализатор профилей VSCode (@profview_allocs) [необходимы документы]
• Просмотр результатов напрямую в REPL
  • Вы можете просмотреть результаты в REPL с помощью Profile.Allocs.fetch(), чтобы увидеть трассировку стека и тип каждого выделения.

Отслеживание распределения по строкам

Альтернативный способ измерения распределения — запустить 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.

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