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

Использование профилировщика

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

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

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

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

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

$ tarantool test.lua

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

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

@<имя_файла>:<номер_строки>: <количество_событий> events +<выделенные_байты> bytes -<освобожденные_байты> bytes

Вопросы и ответы

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

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

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

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

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

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

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

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

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

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

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

 1local fiber = require "fiber"
 2local log = require "log"
 3
 4fiber.create(function()
 5  fiber.name("memprof")
 6
 7  collectgarbage() -- Сбор мертвых объектов
 8  log.warn("start of profile")
 9
10  local st, err = misc.memprof.start(ИМЯ_ФАЙЛА)
11  if not st then
12    log.error("failed to start profiler: %s", err)
13  end
14
15  fiber.sleep(ВРЕМЯ)
16
17  collectgarbage()
18  st, err = misc.memprof.stop()
19
20  if not st then
21    log.error("profiler on stop error: %s", err)
22  end
23
24  log.warn("end of profile")
25end)

Пояснения:

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

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

Пример анализа отчета о профилировании

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

 1-- Отключение аллокации на новых трассах
 2jit.off()
 3
 4local function concat(a)
 5  local nstr = a.."a"
 6  return nstr
 7end
 8
 9local function format(a)
10  local nstr = string.format("%sa", a)
11  return nstr
12end
13
14collectgarbage()
15
16local binfile = "/tmp/memprof_"..(arg[0]):match("([^/]*).lua")..".bin"
17
18local st, err = misc.memprof.start(binfile)
19assert(st, err)
20
21-- Нагрузка
22for i = 1, 10000 do
23  local f = format(i)
24  local c = concat(i)
25end
26collectgarbage()
27
28local st, err = misc.memprof.stop()
29assert(st, err)
30
31os.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()?
• Почему количество событий — это не целое число?
• Why are there about 20K allocations instead of 10K?

Во-первых, 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, вы увидите разницу в поведении.

To profile only the concat() function, comment out line 23 (which is local f = format(i)) and run the profiler. Now the output looks like this:

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

Сводка изменений в динамической памяти и параметр –leak-only

Эта функциональная возможность появилась в версии 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.