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

Модуль 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()

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

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 ./julia /test/fastmath.jl
$ perf report --call-graph -G

Существует много других интересных вещей, которые вы можете измерить в своей программе, чтобы получить исчерпывающий список, пожалуйста, ознакомьтесь со страницей примеров Linux perf .

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