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

Модуль 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, причём каждый член этой семьи предоставляет различные пользовательские интерфейсы:

• VS Code — это полная IDE с встроенной поддержкой визуализации профилей
• ProfileView.jl — автономный визуализатор, основанный на GTK
• ProfileVega.jl использует VegaLight и хорошо интегрируется с Jupyter-тетрадями
• StatProfilerHTML.jl генерирует HTML и предоставляет дополнительные сводки, а также хорошо интегрируется с Jupyter-тетрадями
• ProfileSVG.jl отображает SVG
• PProf.jl предоставляет локальный веб-сайт для проверки графиков, диаграмм пламени и не только
• ProfileCanvas.jl — визуализатор профилей на основе HTML-холста, используемый расширением Julia VS Code, но также может генерировать интерактивные HTML-файлы.

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

Ведение журнала GC

В то время как @time регистрирует высокоуровневую статистику об использовании памяти и сборке мусора в процессе оценки выражения, может быть полезно регистрировать каждое событие сбора мусора, чтобы получить интуитивное представление о том, как часто запускается сборщик мусора, сколько времени он тратит каждый раз и сколько мусора он собирает каждый раз. Это можно включить с помощью GC.enable_logging(true), что заставляет Julia регистрировать в stderr каждый раз, когда происходит сбор мусора.

Профилировщик выделений

Профилировщик выделений записывает трассировку стека, тип и размер каждого выделения во время его работы. Он может быть вызван с помощью Profile.Allocs.@profile.

Эта информация об выделениях возвращается в виде массива объектов Alloc, заключенных в объект AllocResults. Лучший способ визуализировать их в настоящее время — с помощью пакетов PProf.jl и ProfileCanvas.jl, которые могут визуализировать стеки вызовов, совершающие наибольшее количество выделений.

Профилировщик выделений имеет значительные накладные расходы, поэтому аргумент sample_rate можно передать, чтобы ускорить его работу, пропуская некоторые выделения. Передача sample_rate=1.0 заставит его записывать все (что медленно); sample_rate=0.1 — записывать только 10% выделений (быстрее) и т. д.

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

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