Top.Mail.Ru
Профилировщик памяти LuaJIT | Tarantool
Tarantool
Узнайте содержание релиза 2.8
Сервер приложений Профилировщик памяти LuaJIT

Профилировщик памяти LuaJIT

В Tarantool, начиная с версии 2.7.1, есть встроенный модуль misc.memprof, реализующий профилировщик памяти LuaJIT (далее в разделе — профилировщик). Профилировщик предоставляет отчет об аллокации памяти, который помогает проанализовать Lua-код и выявить области наибольшей нагрузки на сборщик мусора на Lua.

Работа с профилировщиком состоит из двух этапов:

  1. События аллокации, реаллокации и деаллокации в Lua собираются в бинарный профиль (далее по тексту — бинарный профиль памяти или просто бинарный профиль).
  2. Выполняется парсинг собранного бинарного профиля. В результате формируется отчет о профилировании в удобном для чтения формате.

Чтобы сформировать бинарный профиль для определенного участка кода на Lua, вставьте этот участок кода между функциями misc.memprof.start() и misc.memprof.stop(), а затем выполните его в Tarantool.

Для наглядности ниже приведен фрагмент кода на Lua под названием test.lua.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
-- Отключение аллокации на трассах
jit.off()
local str, err = misc.memprof.start("memprof_new.bin")
-- Lua не создает стековый фрейм для вызова string.rep,
-- поэтому все события аллокации
-- приписываются не функции append(), а родительской области
local function append(str, rep)
    return string.rep(str, rep)
end

local t = {}
for i = 1, 1e4 do
    -- table.insert — встроенная функция,
    -- так что профилировщик включает все соответствующие ей
    -- события аллокации в отчет по основной части кода
    table.insert(t,
        append('q', i)
    )
end
local stp, err = misc.memprof.stop()

В примере test.lua код для запуска профилировщика находится на строке 3:

local str, err = misc.memprof.start(ИМЯ_ФАЙЛА)

ИМЯ_ФАЙЛА — имя бинарного файла, куда записываются профилируемые события.

Если операция завершается ошибкой, функция misc.memprof.start() возвращает результат, состоящий из трех частей: nil; строка с сообщением об ошибке; код ошибки в зависимости от системы. Ошибка может возникнуть, например, когда не открывается файл для записи или профилировщик уже запущен. Если операция выполняется успешно, misc.memprof.start() возвращает true.

В примере test.lua код для остановки профилировщика находится на строке 18:

local stp, err = misc.memprof.stop()

Если операция завершается ошибкой, функция misc.memprof.stop() возвращает результат, состоящий из трех частей: nil; строка с сообщением об ошибке; код ошибки в зависимости от системы. Ошибка может возникнуть, например, когда закрыт файловый дескриптор или во время составления отчета происходит сбой. Если операция выполняется успешно, misc.memprof.stop() возвращает true.

Теперь нужно сгенерировать файл с профилем памяти в бинарном формате. В примере test.lua имя файла — memprof_new.bin. Выполните код в Tarantool:

$ tarantool test.lua

Tarantool собирает события аллокации в файл memprof_new.bin, помещает его в рабочую директорию и завершает сеанс.

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

  • Строка 2: Рекомендуется отключать JIT-компиляцию, вызывая jit.off() перед запуском профилировщика. За дополнительными сведениями обратитесь к примечанию о jitoff.
  • Строки 6–8: Оптимизация хвостового вызова не создает новый фрейм стека вызовов, поэтому все события аллокации в байт-коде CALLT/CALLMT относятся на счет кода, вызывающего эту функцию. Обратите внимание на комментарии перед этими строками.
  • Строки 14–16: Как правило, разработчиков несильно интересует информация об аллокации во встроенных функциях LuaJIT. Поэтому если встроенная функция вызывается из функции на Lua, профилировщик собирает все события аллокации для функции на Lua. В противном случае событие относится к функции на C. Обратите внимание на комментарии перед этими строками.

Получив профиль памяти в двоичном формате, нужно выполнить парсинг, чтобы отчет было удобно читать. Парсинг можно выполнить в Tarantool, воспользовавшись следующей командой (обратите внимание на дефис - перед именем файла):

$ tarantool -e 'require("memprof")(arg)' - memprof_new.bin

Здесь memprof_new.bin — бинарный профиль, ранее сгенерированный командой tarantool test.lua. (Внимание: в версии Tarantool 2.8.1 поведение команды tarantool -e немного изменилось.)

Tarantool генерирует отчет о профилировании и выводит его в консоль перед закрытием сеанса:

ALLOCATIONS
@test.lua:14: 10000 events  +50240518 bytes -0 bytes
@test.lua:9: 1 events       +32 bytes       -0 bytes
@test.lua:8: 1 events       +20 bytes       -0 bytes
@test.lua:13: 1 events      +24 bytes       -0 bytes

REALLOCATIONS
@test.lua:13: 13 events     +262216 bytes   -131160 bytes
    Overrides:
        @test.lua:13

@test.lua:14: 11 events     +49536 bytes    -24768 bytes
            Overrides:
        @test.lua:14
        INTERNAL

INTERNAL: 3 events          +8448 bytes     -16896 bytes
    Overrides:
        @test.lua:14

DEALLOCATIONS
INTERNAL: 1723 events       +0 bytes        -483515 bytes
@test.lua:14: 1 events      +0 bytes        -32768 bytes

HEAP SUMMARY:
@test.lua:14 holds 50248326 bytes: 10010 allocs, 10 frees
@test.lua:13 holds 131080 bytes: 14 allocs, 13 frees
INTERNAL holds 8448 bytes: 3 allocs, 3 frees
@test.lua:9 holds 32 bytes: 1 allocs, 0 frees
@test.lua:8 holds 20 bytes: 1 allocs, 0 frees

Примечание

В macOS отчет по той же части кода выглядит по-другому, поскольку Tarantool и LuaJIT собраны с поддержкой режима GC64 для macOS.

Рассмотрим структуру отчета. Он состоит из четырех разделов:

  • ALLOCATIONS (аллокация)
  • REALLOCATIONS (реаллокация)
  • DEALLOCATIONS (деаллокация)
  • HEAP SUMMARY (cводка изменений в динамической памяти, раздел описан ниже)

Записи в каждом разделе отсортированы в порядке от наиболее до наименее частых событий.

Запись о событии регистрируется в следующем формате:

@<имя_файла>:<номер_строки>: <количество_событий> events +<выделенные_байты> bytes -<освобожденные_байты> bytes
  • <имя_файла> — имя файла, содержащего код на Lua.
  • <номер_строки> — номер строки, в которой обнаружено событие.
  • <количество_событий> — количество событий для этой строки кода.
  • +<выделенная_память_в_байтах> bytes — объем выделенной памяти для всех событий в этой строке.
  • +<освобожденная_память_в_байтах> bytes — объем освобожденной памяти для всех событий в этой строке.

Метка Overrides на событии показывает, какое событие аллокации оно замещает.

См. код примера test.lua выше и пояснения в комментариях к нему.

Метка INTERNAL показывает, что событие произошло во внутренних структурах LuaJIT.

Примечание

Важное примечание о метке INTERNAL и рекомендации отключать компиляцию JIT (jit.off()). В текущей версии профилировщика не поддерживается подробное (verbose) описание событий аллокации при трассировке. Если память выделяется во время трассировки, профилировщик не может соотнести события аллокации с соответствующей частью кода. В этом случае профилировщик помечает такие события как INTERNAL.

Когда компиляция JIT включена, выполняется несколько процессов трассировки. В результате пометку INTERNAL в отчете о профилировании получают самые разные события: некоторые из них действительно возникают во внутренних структурах LuaJIT, а другие вызваны аллокацией при трассировке.

Вы можете получить более конкретный отчет, в который не входят события аллокации, вызванные JIT-компилятором. Для этого до запуска профилировщика вызовите jit.off(). Чтобы полностью исключить из отчета аллокацию на трассах, удалите предыдущие трассы, вызвав после jit.off() функцию jit.flush().

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

Иногда отчет о профилировании помогает исследовать код на Lua. Однако этот метод подходит не для любого кода, так что рекомендаций на этот счет нет. Посмотрите пример анализа отчета о профилировании, чтобы узнать, как можно использовать отчет для исследования кода.

Больше информации о том, как использовать профилировщик, вы найдете ниже в разделе Вопросы и ответы.

В этом разделе даются ответы на часто задаваемые вопросы о работе профилировщика.

Вопрос (В): Проверяет ли профилировщик аллокацию в C и коде на C?

Ответ (A): Профилировщик включает в отчет только события выделения памяти Lua-аллокатором. Отчет содержит все события аллокации в Lua, например создание таблиц и строк. Однако профилировщик не отслеживает выделение памяти с помощью malloc() или действия аллокаторов, не связанных с Lua. Чтобы фиксировать такие события, для отладки можно использовать valgrind.


В: Почему у меня в отчете о профилировании столько событий аллокации INTERNAL? Что это значит?

О: Пометка INTERNAL означает, что событие аллокации/реаллокации/деаллокации связано с внутренними структурами LuaJIT или трассами. Сейчас профилировщик не включает в отчет подробное описание событий аллокации для объектов, создаваемых на трассах. Попробуйте перед запуском профилировщика добавить jit.off().


В: Почему на некоторых событиях аллокации/деаллокации нет метки Overrides?

О: Вероятно, события связаны с объектами, созданными до запуска профилировщика. Если перед запуском профилировщика добавить вызов collectgarbage(), то будут учитываться и события, связанные с «мертвыми» объектами: под такие объекты ранее была выделена память, но на момент запуска профилировщика они уже недоступны.


В: Почему некоторые объекты не учитываются при профилировании? Это связано с утечкой памяти?

О: LuaJIT использует инкрементальный сборщик мусора. Когда профилировщик завершает работу, цикл сборки мусора может все еще выполняться. Чтобы обеспечить профилирование «мертвых» объектов, добавьте collectgarbage() перед командой остановки профилировщика.


В: Можно ли профилировать не только часть кода, а все приложение? Можно ли запустить профилировщик во время работы приложения?

О: Да. Вот пример кода, который можно вставить в консоль Tarantool, когда приложение уже запущено:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
local fiber = require "fiber"
local log = require "log"

fiber.create(function()
  fiber.name("memprof")

  collectgarbage() -- Сбор мертвых объектов
  log.warn("start of profile")

  local st, err = misc.memprof.start(ИМЯ_ФАЙЛА)
  if not st then
    log.error("failed to start profiler: %s", err)
  end

  fiber.sleep(ВРЕМЯ)

  collectgarbage()
  st, err = misc.memprof.stop()

  if not st then
    log.error("profiler on stop error: %s", err)
  end

  log.warn("end of profile")
end)

Пояснения:

  • ИМЯ_ФАЙЛА — имя бинарного файла, куда записываются профилируемые события.
  • ВРЕМЯ — продолжительность профилирования в секундах.

Кроме того, вызывать misc.memprof.start() и misc.memprof.stop() можно напрямую из консоли.

Ниже приведен код на Lua — файл format_concat.lua. Этот код будет исследован с применением отчетов о профилировании памяти.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
-- Отключение аллокации на новых трассах
jit.off()

local function concat(a)
  local nstr = a.."a"
  return nstr
end

local function format(a)
  local nstr = string.format("%sa", a)
  return nstr
end

collectgarbage()

local binfile = "/tmp/memprof_"..(arg[0]):match("([^/]*).lua")..".bin"

local st, err = misc.memprof.start(binfile)
assert(st, err)

-- Нагрузка
for i = 1, 10000 do
  local f = format(i)
  local c = concat(i)
end
collectgarbage()

local st, err = misc.memprof.stop()
assert(st, err)

os.exit()

Запустив этот код в Tarantool и выполнив последующий парсинг бинарного профиля в /tmp/memprof_format_concat.bin, вы получите такой отчет о профилировании:

ALLOCATIONS
@format_concat.lua:10: 19996 events +624284 bytes   -0 bytes
INTERNAL: 1 events                  +65536 bytes    -0 bytes

REALLOCATIONS

DEALLOCATIONS
INTERNAL: 19996 events              +0 bytes        -558778 bytes
    Overrides:
        @format_concat.lua:10

@format_concat.lua:10: 2 events     +0 bytes        -98304 bytes
    Overrides:
        @format_concat.lua:10

HEAP SUMMARY:
INTERNAL holds 65536 bytes: 1 allocs, 0 frees

Отчет может вызвать такие вопросы:

  • Почему нет событий по функции concat()?
  • Почему количество событий — это не целое число?
  • Почему в отчете не 10 тысяч событий, а около 20 тысяч?

Во-первых, LuaJIT не создает новую строку, если уже есть строка с такой же нагрузкой (подробнее на сайте lua-users.org/wiki). Это называется интернированием строк. Иными словами, если строка создана с помощью функции format(), нет необходимости создавать такую же строку с помощью функции concat() — LuaJIT будет использовать предыдущую.

По этой же причине количество событий аллокации — это не целое число, как можно было бы ожидать при использовании оператора цикла for i = 1, 10000.... Некоторые строки Tarantool создает для внутренних нужд и встроенных модулей, поэтому часть строк уже существует.

Но откуда столько событий аллокации? Их почти в 2 раза больше, чем можно было бы ожидать. Это происходит потому, что встроенная функция string.format() каждый раз создает дополнительную строку для идентификатора %s. То есть в каждой итерации регистрируются два события аллокации: для tostring(i) и для string.format("%sa", string_i_value). Добавив строку local _ = tostring(i) между строками 22 и 23, вы увидите разницу в поведении.

Чтобы профилировать только функцию concat(), закомментируйте строку 23 (local f = format(i)) и запустите профилировщик. Теперь результат будет такой:

ALLOCATIONS
@format_concat.lua:5: 10000 events  +284411 bytes    -0 bytes

REALLOCATIONS

DEALLOCATIONS
INTERNAL: 10000 events              +0 bytes         -218905 bytes
    Overrides:
        @format_concat.lua:5

@format_concat.lua:5: 1 events      +0 bytes         -32768 bytes

HEAP SUMMARY:
@format_concat.lua:5 holds 65536 bytes: 10000 allocs, 9999 frees

В: Что изменится, если включить компиляцию JIT?

О: Закомментируйте вторую строку (jit.off()) в коде и запустите профилировщик. Теперь в отчете только 56 событий. Остальные события связаны с JIT (см. также соответствующую задачу на GitHub):

ALLOCATIONS
@format_concat.lua:5: 56 events +1112 bytes -0 bytes
@format_concat.lua:0: 4 events  +640 bytes  -0 bytes
INTERNAL: 2 events              +382 bytes  -0 bytes

REALLOCATIONS

DEALLOCATIONS
INTERNAL: 58 events             +0 bytes    -1164 bytes
    Overrides:
        @format_concat.lua:5
        INTERNAL


HEAP SUMMARY:
@format_concat.lua:0 holds 640 bytes: 4 allocs, 0 frees
INTERNAL holds 360 bytes: 2 allocs, 1 frees

Так произошло потому, что трассировка была скомпилирована после 56 итераций (это значение параметра компилятора hotloop по умолчанию). Затем JIT-компилятор удалил из трассировки неиспользуемую переменную c, а вместе с ней и неиспользуемый код функции concat().

Теперь включите компиляцию JIT и запустите профилирование только для функции format(). Для этого закомментируйте строки 2 и 24 (jit.off() и local c = concat(i)), раскомментируйте строку 23 (local f = format(i)) и вызовите профилировщик. Результат будет такой:

ALLOCATIONS
@format_concat.lua:10: 19996 events +624284 bytes  -0 bytes
INTERNAL: 4 events                  +66928 bytes   -0 bytes
@format_concat.lua:0: 4 events      +640 bytes     -0 bytes

REALLOCATIONS

DEALLOCATIONS
INTERNAL: 19997 events              +0 bytes       -559034 bytes
    Overrides:
        @format_concat.lua:0
        @format_concat.lua:10

@format_concat.lua:10: 2 events     +0 bytes       -98304 bytes
    Overrides:
        @format_concat.lua:10


HEAP SUMMARY:
INTERNAL holds 66928 bytes: 4 allocs, 0 frees
@format_concat.lua:0 holds 384 bytes: 4 allocs, 1 frees

В: Откуда так много событий аллокации по сравнению с concat()?

О: Ответ прост: LuaJIT еще не скомпилировал функцию string.format() с идентификатором %s. Поэтому трассировка не регистрируется, а компилятор не выполняет соответствующую оптимизацию.

Изменим функцию format в строках 9–12 примера для анализа отчета о профилировании следующим образом:

local function format(a)
  local nstr = string.format("%sa", tostring(a))
  return nstr
end

Теперь отчет о профилировании будет выглядеть намного лучше:

ALLOCATIONS
@format_concat.lua:10: 109 events   +2112 bytes -0 bytes
@format_concat.lua:0: 4 events      +640 bytes  -0 bytes
INTERNAL: 3 events                  +1206 bytes -0 bytes

REALLOCATIONS

DEALLOCATIONS
INTERNAL: 112 events                +0 bytes    -2460 bytes
    Overrides:
        @format_concat.lua:0
        @format_concat.lua:10
        INTERNAL


HEAP SUMMARY:
INTERNAL holds 1144 bytes: 3 allocs, 1 frees
@format_concat.lua:0 holds 384 bytes: 4 allocs, 1 frees

Эта функциональная возможность появилась в версии 2.8.1.

В конце каждого отчета приводится раздел HEAP SUMMARY (сводка изменений в динамической памяти). Этот раздел выглядит так:

@<имя_файла>:<номер_строки> holds <количество_доступных_байтов> bytes: <количество_событий_аллокации> allocs, <количество_событий_деаллокации> frees

Иногда программа может вызывать множество событий деаллокации. В этом случае раздел DEALLOCATION сильно увеличится и отчет будет сложно читать. Чтобы уменьшить количество выводимых данных, запустите парсинг с дополнительным параметром --leak-only. Например, так:

$ tarantool -e 'require("memprof")(arg)' - --leak-only memprof_new.bin

При использовании параметра --leak-only выводится только раздел HEAP SUMMARY.