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

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

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