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

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

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

Одним из наиболее распространенных способов повышения производительности является сокращение выделения памяти. 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.

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

Хотя @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% выделений (быстрее) и т. д.

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

В настоящее время 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, помните, чтобы часто очищать эту папку.