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

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

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

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

Выборочный профайлер не обеспечивает полное строчное покрытие, так как обратные отслеживающие журналы происходят с интервалами (по умолчанию 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> @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.

Первая строка показывает, что в строке 73 файла event.jl было взято 80 обратных отслеживающих журналов, но не в том смысле, что эта строка была «дорогой» сама по себе: третья строка показывает, что все 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.

© 2009–2016 Jeff Bezanson, Stefan Karpinski, Viral B. Shah, and other contributors
Licensed under the MIT License.
https://docs.julialang.org/en/release-0.6/manual/profile/