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

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

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

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

Профайлер отбора не обеспечивает полного построчного покрытия, потому что трассировки стека происходят через интервалы (по умолчанию 1 мс на Unix-системах и 10 мс на Windows, хотя фактическое планирование зависит от нагрузки операционной системы). Кроме того, как обсуждается ниже, поскольку образцы собираются в разреженной подвыборке всех точек выполнения, данные, собранные профайлером отбора, подвержены статистическому шуму.

Несмотря на эти ограничения, у профайлеров отбора есть существенные преимущества:

Вам не нужно вносить какие-либо изменения в свой код для проведения измерений времени (в отличие от альтернативного профайлера с инструментированием).
Он может производить профилирование кода ядра Julia и даже (по выбору) кода библиотек C и Fortran.
За счёт «редкого» выполнения, он имеет очень небольшую нагрузку на производительность; во время профилирования ваш код может работать практически с родной скоростью.

По этим причинам рекомендуется попробовать использовать встроенный профайлер отбора, прежде чем рассматривать какие-либо альтернативы.

Основное использование

Давайте поработаем с простым тестовым случаем:

function myfunc()
    A = rand(100, 100, 200)
    maximum(A)
end

Хорошо сначала запустить код, который вы хотите проанализировать, хотя бы один раз (если вы не хотите профилировать JIT-компилятор Julia):

julia> myfunc()  # run once to force compilation

Теперь мы готовы профилировать эту функцию:

julia> @profile myfunc()

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

julia> Profile.print()
      23 client.jl; _start; line: 373
        23 client.jl; run_repl; line: 166
           23 client.jl; eval_user_input; line: 91
              23 profile.jl; anonymous; line: 14
                 8  none; myfunc; line: 2
                  8 dSFMT.jl; dsfmt_gv_fill_array_close_open!; line: 128
                 15 none; myfunc; line: 3
                  2  reduce.jl; max; line: 35
                  2  reduce.jl; max; line: 36
                  11 reduce.jl; max; line: 37

Каждая строка этого вывода представляет собой определённую точку (номер строки) в коде. Отступы используются для обозначения вложенной последовательности вызовов функций, причём строки с большими отступами находятся глубже в последовательности вызовов. В каждой строке первое «поле» указывает количество трассировок стека (образцов), взятых в этой строке или в любых функциях, выполненных этой строкой. Второе поле — имя файла, за которым следует точка с запятой; третье — имя функции, за которым следует точка с запятой, и четвёртое — номер строки. Обратите внимание, что конкретные номера строк могут меняться при изменении кода Julia; если вы хотите следовать этому примеру, лучше всего запустить этот пример самостоятельно.

В этом примере мы видим, что верхнем уровне находится client.jl‘s _start функция. Это первая функция Julia, которая вызывается при запуске Julia. Если вы изучите строку 373 в client.jl, вы увидите, что (на момент написания этого документа) она вызывает run_repl(), упомянутую во второй строке. Это, в свою очередь, вызывает eval_user_input(). Это функции в client.jl интерпретируют вводимые вами данные в интерактивной оболочке, и так как мы работаем интерактивно, эти функции были вызваны, когда мы ввели @profile myfunc(). Следующая строка отражает действия, выполненные в макросе @profile.

Первая строка показывает, что 23 трассировки стека были взяты в строке 373 в client.jl, но это не значит, что эта строка была «дорогой» сама по себе: вторая строка показывает, что все 23 этих трассировки стека были фактически инициированы внутри вызова run_repl, и так далее. Чтобы узнать, какие операции фактически занимают время, нам нужно посмотреть глубже в цепочке вызовов.

Первая «важная» строка в этом выводе — вот она:

8  none; myfunc; line: 2

none относится к тому факту, что мы определили myfunc в интерактивной оболочке, а не поместили его в файл; если бы мы использовали файл, здесь было бы указано имя файла. Строка 2 myfunc() содержит вызов rand, и здесь было 8 (из 23) трассировок стека, которые произошли в этой строке. Ниже вы можете увидеть вызов dsfmt_gv_fill_array_close_open!() внутри dSFMT.jl. Возможно, вы удивитесь, что функция rand не указана явно: это потому, что rand выполняется встроенно, а поэтому не отображается в трассировках стека.

Немного ниже вы видите:

15 none; myfunc; line: 3

Строка 3 myfunc содержит вызов max, и здесь было 15 (из 23) трассировок стека. Ниже вы можете увидеть конкретные места в base/reduce.jl, которые выполняют трудоёмкие операции в функции max для этого типа входных данных.

В целом, можно предварительно заключить, что поиск максимального элемента примерно в два раза дороже, чем генерация случайных чисел. Мы могли бы повысить уверенность в этом результате, собрав больше образцов:

julia> @profile (for i = 1:100; myfunc(); end)

julia> Profile.print()
       3121 client.jl; _start; line: 373
        3121 client.jl; run_repl; line: 166
           3121 client.jl; eval_user_input; line: 91
              3121 profile.jl; anonymous; line: 1
                 848  none; myfunc; line: 2
                  842 dSFMT.jl; dsfmt_gv_fill_array_close_open!; line: 128
                 1510 none; myfunc; line: 3
                  74   reduce.jl; max; line: 35
                  122  reduce.jl; max; line: 36
                  1314 reduce.jl; max; line: 37

В общем случае, если у вас N образцов, собранных в строке, вы можете ожидать неопределённости порядка sqrt(N) (исключая другие источники шума, такие как загруженность компьютера другими задачами). Главное исключение из этого правила — сборка мусора, которая выполняется редко, но, как правило, довольно ресурсоёмка. (Поскольку сборщик мусора Julia написан на C, такие события можно обнаружить с помощью режима вывода C=true описанного ниже, или с помощью ProfileView.jl.)

Это иллюстрирует вывод по умолчанию в «дерево»; альтернатива — «плоский» вывод, который накапливает счётчики независимо от их вложенности:

julia> Profile.print(format=:flat)
 Count File         Function                         Line
  3121 client.jl    _start                            373
  3121 client.jl    eval_user_input                    91
  3121 client.jl    run_repl                          166
   842 dSFMT.jl     dsfmt_gv_fill_array_close_open!   128
   848 none         myfunc                              2
  1510 none         myfunc                              3
  3121 profile.jl   anonymous                           1
    74 reduce.jl    max                                35
   122 reduce.jl    max                                36
  1314 reduce.jl    max                                37

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

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(); format = :tree, C = false, combine = true, cols = tty_cols(), maxdepth = typemax(Int), sortedby = :filefuncline)

Давайте обсудим эти аргументы по порядку:

Первый аргумент позволяет сохранить результаты в файл, но по умолчанию результаты выводятся в STDOUT (консоль).
Второй аргумент содержит данные, которые вы хотите проанализировать; по умолчанию эти данные берутся из 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. Попробуйте запустить вводный пример с Profile.print(C = true). Это может быть чрезвычайно полезно при определении, является ли узким местом код Julia или C; установка C=true также улучшает интерпретируемость вложенности, за счёт более длинных выводов профиля.
Некоторые строки кода содержат несколько операций; например, s += A[i] содержит как обращение к массиву (A[i]), так и операцию сложения. Они соответствуют различным строкам в сгенерированном машинном коде, и поэтому при трассировке стека в этой строке может быть зафиксировано два или более различных указателя инструкций. combine=true объединяет их, и это, вероятно, то, что вы обычно хотите, но вы можете сгенерировать отдельный вывод для каждого уникального указателя инструкции с помощью combine=false.
cols позволяет управлять количеством столбцов, которые вы готовы использовать для отображения. Когда текст будет шире, чем область отображения, вы можете увидеть вывод, подобный этому:
```
33 inference.jl; abstract_call; line: 645
  33 inference.jl; abstract_call; line: 645
    33 ...rence.jl; abstract_call_gf; line: 567
       33 ...nce.jl; typeinf; line: 1201
     +1 5  ...nce.jl; ...t_interpret; line: 900
     +3 5 ...ence.jl; abstract_eval; line: 758
     +4 5 ...ence.jl; ...ct_eval_call; line: 733
     +6 5 ...ence.jl; abstract_call; line: 645
```
Имена файлов/функций иногда усекаются (с помощью ...), а отступы усекаются с +n в начале, где n — количество дополнительных пробелов, которые были бы вставлены, если бы было место. Если вы хотите получить полный профиль глубоко вложенного кода, зачастую хорошей идеей является сохранение в файл и использование очень широкого значения cols:
```
s = open("/tmp/prof.txt","w")
Profile.print(s,cols = 500)
close(s)
```
maxdepth может быть использован для ограничения размера вывода в формате :tree (он вкладывает только до уровня maxdepth)
sortedby = :count сортирует формат :flat по возрастанию счётчиков

Настройка

@profile просто накапливает трассировки стека вызовов, а анализ происходит при вызове Profile.print(). Для длительных вычислений вполне возможно, что предварительно выделенный буфер для хранения трассировок стека вызовов заполнится. Если это произойдет, трассировки стека вызовов остановятся, но ваши вычисления продолжатся. Вследствие этого, вы можете пропустить некоторые важные данные профилирования (вы получите предупреждение, когда это произойдет).

Вы можете получить и настроить соответствующие параметры следующим образом:

Profile.init()            # returns the current settings
Profile.init(n, delay)
Profile.init(delay = 0.01)

n — это общее количество указателей инструкций, которые вы можете сохранить, со значением по умолчанию 10^6. Если типичная трассировка стека вызовов содержит 20 указателей инструкций, то вы можете собрать 50000 трассировок стека вызовов, что предполагает статистическую неопределённость менее 1%. Это может быть достаточно для большинства применений.

Следовательно, вам, скорее всего, придётся изменить delay, выраженное в секундах, что устанавливает интервал времени, который Julia получает между моментами отбора проб для выполнения запрошенных вычислений. Для очень длительных задач может не потребоваться частые трассировки стека вызовов. Значение по умолчанию — delay = 0.001. Конечно, вы можете уменьшить, а также увеличить задержку; однако, накладные расходы на профилирование возрастают, когда задержка становится сопоставимой со временем, необходимым для получения трассировки стека вызовов (~30 микросекунд на ноутбуке автора).

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