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

Модуль 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 генерирует HTML и предоставляет некоторые дополнительные сводки, а также хорошо интегрируется с Jupyter-тетрадками.
• ProfileSVG отображает SVG.

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

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

Чтобы измерить выделение по строкам, запустите 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.

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