Документация Engee

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

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

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

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

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

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

  • Вам не нужно вносить изменения в код для проведения измерений времени.

  • Профилировщик может профилировать основной код Julia и даже (необязательно) библиотеки C и Fortran.

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

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

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

Поработаем с простым тестовым примером:

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

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

julia> myfunc() # запустить один раз для принудительного выполнения компиляции

Теперь все готово для профилирования этой функции:

julia> using Profile

julia> @profile myfunc()

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

  • Juno является полнофункциональной средой IDE со встроенной поддержкой визуализации профиля.

  • ProfileView.jl — это автономный визуализатор на основе GTK.

  • ProfileVega.jl использует VegaLight и хорошо интегрируется с записными книжками Jupyter.

  • StatProfilerHTML.jl создает HTML-код и представляет некоторые дополнительные сводки, а также хорошо интегрируется с записными книжками Jupyter.

  • ProfileSVG.jl отрисовывает SVG.

  • PProf.jl предоставляет локальный веб-сайт для просмотра графов, flamegraph и т. п.

Полностью независимым подходом к визуализации профилирования является 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) # Выводит предыдущие результаты
    Profile.print()                      # Выводит результаты из функции 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() # возвращает текущие параметры
Profile.init(n = 10^7, delay = 0.01)

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

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

Анализ выделения памяти

Одним из наиболее распространенных методов повышения производительности является уменьшение объема выделяемой памяти. В Julia доступно несколько инструментов для измерения памяти:

@time

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

Построчное отслеживание выделения

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

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

Ведение журнала статистики сборки мусора

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

Профилировщик выделений

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

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

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

Текущая реализация профилировщика выделений не записывает типы для всех выделений. Выделения, тип которых профилировщик не смог записать, представлены как имеющие тип Profile.Allocs.UnknownType.

Дополнительные сведения о недостающих типах и планах по исправлению ситуации см. здесь: https://github.com/JuliaLang/julia/issues/43688[https://github.com/JuliaLang/julia/issues/43688].

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

Сейчас 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. Не забывайте регулярно очищать ее.