[Tarantool-patches] [PATCH luajit v4 4/4] memprof: add info about trace start to symtab
Mikhail Shishatskiy
m.shishatskiy at tarantool.org
Wed Nov 24 15:42:34 MSK 2021
Sorry, I forgot to remove unnecessary changes in the <process> module!
The demangler now returns the full string, so we can use it as a key
in tables and there will not be any collisions of trace numbers.
Diff:
=============================================================
diff --git a/tools/memprof.lua b/tools/memprof.lua
index 760122fc..18b44fdd 100644
--- a/tools/memprof.lua
+++ b/tools/memprof.lua
@@ -104,8 +104,8 @@ local function dump(inputfile)
if not leak_only then
view.profile_info(events, symbols)
end
- local dheap = process.form_heap_delta(events)
- view.leak_info(dheap, symbols)
+ local dheap = process.form_heap_delta(events, symbols)
+ view.leak_info(dheap)
os.exit(0)
end
diff --git a/tools/memprof/humanize.lua b/tools/memprof/humanize.lua
index dca4826c..7771005d 100644
--- a/tools/memprof/humanize.lua
+++ b/tools/memprof/humanize.lua
@@ -56,16 +56,13 @@ function M.profile_info(events, symbols)
print("")
end
-function M.leak_info(dheap, symbols)
+function M.leak_info(dheap)
local leaks = {}
- for _, info in pairs(dheap) do
+ for line, info in pairs(dheap) do
-- Report "INTERNAL" events inconsistencies for profiling
-- with enabled jit.
if info.dbytes > 0 then
- table.insert(leaks, {
- line = symtab.demangle(symbols, info.loc),
- dbytes = info.dbytes
- })
+ table.insert(leaks, {line = line, dbytes = info.dbytes})
end
end
diff --git a/tools/memprof/process.lua b/tools/memprof/process.lua
index 360f6cc4..0bcb965b 100644
--- a/tools/memprof/process.lua
+++ b/tools/memprof/process.lua
@@ -4,7 +4,7 @@ local M = {}
local symtab = require "utils.symtab"
-function M.form_heap_delta(events)
+function M.form_heap_delta(events, symbols)
-- Auto resurrects source event lines for counting/reporting.
local dheap = setmetatable({}, {__index = function(t, line)
rawset(t, line, {
@@ -17,12 +17,11 @@ function M.form_heap_delta(events)
for _, event in pairs(events.alloc) do
if event.loc then
- local ev_line = symtab.id(event.loc)
+ local ev_line = symtab.demangle(symbols, event.loc)
if (event.alloc > 0) then
dheap[ev_line].dbytes = dheap[ev_line].dbytes + event.alloc
dheap[ev_line].nalloc = dheap[ev_line].nalloc + event.num
- dheap[ev_line].loc = event.loc
end
end
end
@@ -38,18 +37,16 @@ function M.form_heap_delta(events)
-- that references the table with memory changed
-- (may be empty).
for _, heap_chunk in pairs(event.primary) do
- local ev_line = symtab.id(heap_chunk.loc)
+ local ev_line = symtab.demangle(symbols, heap_chunk.loc)
if (heap_chunk.alloced > 0) then
dheap[ev_line].dbytes = dheap[ev_line].dbytes + heap_chunk.alloced
dheap[ev_line].nalloc = dheap[ev_line].nalloc + heap_chunk.count
- dheap[ev_line].loc = heap_chunk.loc
end
if (heap_chunk.freed > 0) then
dheap[ev_line].dbytes = dheap[ev_line].dbytes - heap_chunk.freed
dheap[ev_line].nfree = dheap[ev_line].nfree + heap_chunk.count
- dheap[ev_line].loc = heap_chunk.loc
end
end
end
=============================================================
On 22.11.2021 18:11, Mikhail Shishatskiy via Tarantool-patches wrote:
>Igor,
>Thank you for the review! Hope, I got your comments right :)
>
>New commit message:
>============================================================
>memprof: add info about trace start to symtab
>
>Allocation events occured on traces are recorded by the memory
>profiler the following way now
>
>| TRACE [<trace-no>] <trace-addr>
>
>This approach is not descriptive enough to understand, where
>exactly allocation took place, as we do not know the code
>chunk, associated with the trace.
>
>This patch fixes the problem described above by extending the
>symbol table with <sym-trace> entries, consisting of a trace's
>mcode starting address, trace number, address of function proto,
>and line, where trace recording started:
>
>| sym-trace := sym-header trace-no trace-addr sym-addr sym-line
>| trace-no := <ULEB128>
>| trace-addr := <ULEB128>
>
>The memory profiler parser is adjusted to recognize the entries
>mentioned above. On top of that, the API of <utils/symtab.lua> changed:
>now table with symbols contains two tables: `lfunc` for Lua functions
>symbols and `trace` for trace entries.
>
>+ If the trace is in the symtab, it will be associated with a proto
>+ by the <symtab.demangle>, and one will get an output in the format
>+ described below:
>
>| TRACE [<trace-no>] <trace-addr> started at @<sym-chunk>:<sym-line>
>
>Follows up tarantool/tarantool#5814
>============================================================
>
>The diff:
>============================================================
>diff --git a/tools/memprof/humanize.lua b/tools/memprof/humanize.lua
>index caab8b3a..dca4826c 100644
>--- a/tools/memprof/humanize.lua
>+++ b/tools/memprof/humanize.lua
>@@ -7,23 +7,6 @@ local symtab = require "utils.symtab"
>
> local M = {}
>
>-local function describe_location(symbols, loc)
>- if loc.traceno == 0 then
>- return symtab.demangle(symbols, loc)
>- end
>-
>- local trace = symbols.trace[loc.traceno]
>-
>- -- If trace, which was remembered in the symtab, has not
>- -- been flushed, associate it with a proto, where trace
>- -- recording started.
>- if trace and trace.addr == loc.addr then
>- return symtab.demangle(symbols, loc).." started at "..
>- symtab.demangle(symbols, trace.start)
>- end
>- return symtab.demangle(symbols, loc)
>-end
>-
> function M.render(events, symbols)
> local ids = {}
>
>@@ -38,7 +21,7 @@ function M.render(events, symbols)
> for i = 1, #ids do
> local event = events[ids[i]]
> print(string.format("%s: %d events\t+%d bytes\t-%d bytes",
>- describe_location(symbols, event.loc),
>+ symtab.demangle(symbols, event.loc),
> event.num,
> event.alloc,
> event.free
>@@ -46,7 +29,7 @@ function M.render(events, symbols)
>
> local prim_loc = {}
> for _, heap_chunk in pairs(event.primary) do
>- table.insert(prim_loc, describe_location(symbols, heap_chunk.loc))
>+ table.insert(prim_loc, symtab.demangle(symbols, heap_chunk.loc))
> end
> if #prim_loc ~= 0 then
> table.sort(prim_loc)
>@@ -80,7 +63,7 @@ function M.leak_info(dheap, symbols)
> -- with enabled jit.
> if info.dbytes > 0 then
> table.insert(leaks, {
>- line = describe_location(symbols, info.loc),
>+ line = symtab.demangle(symbols, info.loc),
> dbytes = info.dbytes
> })
> end
>diff --git a/tools/utils/symtab.lua b/tools/utils/symtab.lua
>index 879979f8..c7fcf77c 100644
>--- a/tools/utils/symtab.lua
>+++ b/tools/utils/symtab.lua
>@@ -40,7 +40,7 @@ local function parse_sym_trace(reader, symtab)
> symtab.trace[traceno] = {
> addr = trace_addr,
> -- The structure <start> is the same as the one
>- -- yielded from the <parse_location> fucntion
>+ -- yielded from the <parse_location> function
> -- in the <memprof/parse.lua> module.
> start = {
> addr = sym_addr,
>@@ -101,9 +101,28 @@ function M.id(loc)
> return string_format("f%#xl%dt%d", loc.addr, loc.line, loc.traceno)
> end
>
>+local function demangle_trace(symtab, loc)
>+ local traceno = loc.traceno
>+ local addr = loc.addr
>+
>+ assert(traceno ~= 0, "Location is a trace")
>+
>+ local trace_str = string_format("TRACE [%d] %#x", traceno, addr)
>+ local trace = symtab.trace[traceno]
>+
>+ -- If trace, which was remembered in the symtab, has not
>+ -- been flushed, associate it with a proto, where trace
>+ -- recording started.
>+ if trace and trace.addr == addr then
>+ assert(trace.start.traceno == 0, "Trace start is not a trace")
>+ return trace_str.." started at "..M.demangle(symtab, trace.start)
>+ end
>+ return trace_str
>+end
>+
> function M.demangle(symtab, loc)
> if loc.traceno ~= 0 then
>- return string_format("TRACE [%d] %#x", loc.traceno, loc.addr)
>+ return demangle_trace(symtab, loc)
> end
>
> local addr = loc.addr
>============================================================
>
>On 12.11.2021 16:34, Igor Munkin wrote:
>>Misha,
>>
>>Thanks for your fixes! Please consider my answer regarding trace event
>>rendering and a typo in the comment below.
>>
>>On 04.11.21, Mikhail Shishatskiy wrote:
>>>Hi, Igor!
>>>Thank you for the review.
>>>
>>>New commit message:
>>>============================================================
>>>memprof: add info about trace start to symtab
>>>
>>>Allocation events occured on traces are recorded by the memory
>>>profiler the following way now
>>>
>>>| TRACE [<trace-no>] <trace-addr>
>>>
>>>This approach is not descriptive enough to understand, where
>>>exactly allocation took place, as we do not know the code
>>>chunk, associated with the trace.
>>>
>>>This patch fixes the problem described above by extending the
>>>symbol table with <sym-trace> entries, consisting of a trace's
>>>mcode starting address, trace number, address of function proto,
>>>and line, where trace recording started:
>>>
>>>| sym-trace := sym-header trace-no trace-addr sym-addr sym-line
>>>| trace-no := <ULEB128>
>>>| trace-addr := <ULEB128>
>>>
>>>The memory profiler parser is adjusted to recognize the entries
>>>mentioned above. On top of that, the API of <utils/symtab.lua> changed:
>>>now table with symbols contains two tables: `lfunc` for Lua functions
>>>symbols and `trace` for trace entries.
>>>
>>>The demangler module has not changed, but the function
>>>`describe_location` is added to the <memprof/humanize.lua> module,
>>>which allows one to get a description of the trace location in the
>>>format described below:
>>>
>>>| TRACE [<trace-no>] <trace-addr> started at @<sym-chunk>:<sym-line>
>>>
>>>Follows up tarantool/tarantool#5814
>>>============================================================
>>>
>>>Diff:
>>>============================================================
>>>diff --git a/src/lj_memprof.c b/src/lj_memprof.c
>>>index e8b2ebbc..05542052 100644
>>>--- a/src/lj_memprof.c
>>>+++ b/src/lj_memprof.c
>>>@@ -40,7 +40,6 @@ static void dump_symtab_trace(struct lj_wbuf *out, const GCtrace *trace)
>>> startpc < proto_bc(pt) + pt->sizebc);
>>>
>>> lineno = lj_debug_line(pt, proto_bcpos(pt, startpc));
>>>- lua_assert(lineno >= 0);
>>>
>>> lj_wbuf_addbyte(out, SYMTAB_TRACE);
>>> lj_wbuf_addu64(out, (uint64_t)trace->traceno);
>>>diff --git a/test/tarantool-tests/misclib-memprof-lapi.test.lua b/test/tarantool-tests/misclib-memprof-lapi.test.lua
>>>index 3003b9f5..ce667afc 100644
>>>--- a/test/tarantool-tests/misclib-memprof-lapi.test.lua
>>>+++ b/test/tarantool-tests/misclib-memprof-lapi.test.lua
>>>@@ -92,7 +92,7 @@ local function fill_ev_type(events, symbols, event_type)
>>> addr = trace_loc.addr
>>> ev_type.trace[traceno] = {
>>> name = string.format("TRACE [%d] %s:%d",
>>>- traceno, symbols.lfunc[addr].source, symbols.lfunc[addr].linedefined
>>>+ traceno, symbols.lfunc[addr].source, trace_loc.line
>>> ),
>>> num = event.num,
>>> }
>>>@@ -122,7 +122,7 @@ local function check_alloc_report(alloc, location, nevents)
>>> local traceno = location.traceno
>>> if traceno then
>>> expected_name = string.format("TRACE [%d] ", traceno)..
>>>- form_source_line(location.linedefined)
>>>+ form_source_line(location.line)
>>> event = alloc.trace[traceno]
>>> else
>>> expected_name = form_source_line(location.linedefined)
>>>@@ -244,9 +244,7 @@ test:test("jit-output", function(subtest)
>>> local free = fill_ev_type(events, symbols, "free")
>>>
>>> -- We expect, that loop will be compiled into a trace.
>>>- subtest:ok(check_alloc_report(
>>>- alloc, { traceno = 1, line = 37, linedefined = 32 }, 20
>>>- ))
>
><snipped>
>
>>>+ subtest:ok(check_alloc_report(alloc, { traceno = 1, line = 37 }, 20))
>>> -- See same checks with jit.off().
>>> subtest:ok(check_alloc_report(alloc, { line = 34, linedefined = 32 }, 2))
>>> subtest:ok(free.INTERNAL.num == 22)
>>>diff --git a/tools/memprof/humanize.lua b/tools/memprof/humanize.lua
>>>index 7d30f976..caab8b3a 100644
>>>--- a/tools/memprof/humanize.lua
>>>+++ b/tools/memprof/humanize.lua
>>>@@ -7,7 +7,7 @@ local symtab = require "utils.symtab"
>>>
>>> local M = {}
>>>
>>>-function M.describe_location(symbols, loc)
>>>+local function describe_location(symbols, loc)
>>> if loc.traceno == 0 then
>>> return symtab.demangle(symbols, loc)
>>> end
>>>@@ -15,7 +15,7 @@ function M.describe_location(symbols, loc)
>>> local trace = symbols.trace[loc.traceno]
>>>
>>> -- If trace, which was remembered in the symtab, has not
>>>- -- been flushed, assotiate it with a proto, where trace
>>>+ -- been flushed, associate it with a proto, where trace
>>> -- recording started.
>>> if trace and trace.addr == loc.addr then
>>> return symtab.demangle(symbols, loc).." started at "..
>>>@@ -38,7 +38,7 @@ function M.render(events, symbols)
>>> for i = 1, #ids do
>>> local event = events[ids[i]]
>>> print(string.format("%s: %d events\t+%d bytes\t-%d bytes",
>>>- M.describe_location(symbols, event.loc),
>>>+ describe_location(symbols, event.loc),
>>> event.num,
>>> event.alloc,
>>> event.free
>>>@@ -46,7 +46,7 @@ function M.render(events, symbols)
>>>
>>> local prim_loc = {}
>>> for _, heap_chunk in pairs(event.primary) do
>>>- table.insert(prim_loc, M.describe_location(symbols, heap_chunk.loc))
>>>+ table.insert(prim_loc, describe_location(symbols, heap_chunk.loc))
>>> end
>>> if #prim_loc ~= 0 then
>>> table.sort(prim_loc)
>>>@@ -80,7 +80,7 @@ function M.leak_info(dheap, symbols)
>>> -- with enabled jit.
>>> if info.dbytes > 0 then
>>> table.insert(leaks, {
>>>- line = M.describe_location(symbols, info.loc),
>>>+ line = describe_location(symbols, info.loc),
>>> dbytes = info.dbytes
>>> })
>>> end
>>>diff --git a/tools/utils/symtab.lua b/tools/utils/symtab.lua
>>>index 49ebb36f..879979f8 100644
>>>--- a/tools/utils/symtab.lua
>>>+++ b/tools/utils/symtab.lua
>>>@@ -39,6 +39,9 @@ local function parse_sym_trace(reader, symtab)
>>>
>>> symtab.trace[traceno] = {
>>> addr = trace_addr,
>>>+ -- The structure <start> is the same as the one
>>>+ -- yielded from the <parse_location> fucntion
>>
>>Typo: s/fucntion/function/.
>>
>>>+ -- in the <memprof/parse.lua> module.
>>> start = {
>>> addr = sym_addr,
>>> line = sym_line,
>>>============================================================
>>>
>>>Issue: https://github.com/tarantool/tarantool/issues/5814
>>>Branch: https://github.com/tarantool/luajit/tree/shishqa/gh-5814-group-allocations-on-trace-by-trace-number
>>>CI: https://github.com/tarantool/tarantool/tree/shishqa/gh-5814-group-allocations-on-trace-by-trace-number
>>>
>>>On 01.11.2021 19:31, Igor Munkin wrote:
>>>>Misha,
>>>>
>>>>Thanks for the patch! Please consider my comments below.
>>>>
>>>>On 29.09.21, Mikhail Shishatskiy wrote:
>>>>> Trace allocation sources, recorded by the memory profiler,
>>>>> were reported as
>>>
>>><snipped>
>>>
>>>>>
>>>>> | TRACE [<trace-no>] <trace-addr>
>>>>>
>>>>> This approach is not descriptive enough to understand, where
>>>>> exactly allocation took place, as we do not know the code
>>>>> chunk, associated with the trace.
>>>>>
>>>>> This patch fixes the problem described above by extending the
>>>>> symbol table with <sym-trace> entries, consisting of a trace's
>>>>> mcode starting address, trace number, address of function proto,
>>>>> and line, where trace recording started:
>>>>>
>>>>> | sym-trace := sym-header trace-no trace-addr sym-addr sym-line
>>>>> | trace-no := <ULEB128>
>>>>> | trace-addr := <ULEB128>
>>>>>
>>>>> The memory profiler parser is adjusted to recognize the entries
>>>>> mentioned above. On top of that, the API of <utils/symtab.lua> changed:
>>>>> now table with symbols contains two tables: `lfunc` for Lua functions
>>>>> symbols and `trace` for trace entries.
>>>>>
>>>>> The demangler module has not changed, but the function
>>>>> `describe_location` is added to the <memprof/humanize.lua> module,
>>>>> which allows one to get a description of the trace location in the
>>>>> format described below:
>>>>>
>>>>> | TRACE [<trace-no>] <trace-addr> started at @<sym-chunk>:<sym-line>
>>>>>
>>>>> Follows up tarantool/tarantool#5814
>>>>> ---
>>>>>
>>>>> Issue: https://github.com/tarantool/tarantool/issues/5814
>>>>> Branch: https://github.com/tarantool/luajit/tree/shishqa/gh-5814-group-allocations-on-trace-by-trace-number
>>>>> CI: https://github.com/tarantool/tarantool/tree/shishqa/gh-5814-group-allocations-on-trace-by-trace-number
>>>>>
>>>>> src/lj_memprof.c | 43 +++++++++++++++++++
>>>>> src/lj_memprof.h | 8 +++-
>>>>> .../misclib-memprof-lapi.test.lua | 15 ++++---
>>>>> tools/memprof.lua | 4 +-
>>>>> tools/memprof/humanize.lua | 30 ++++++++++---
>>>>> tools/memprof/process.lua | 9 ++--
>>>>> tools/utils/symtab.lua | 31 ++++++++++---
>>>>> 7 files changed, 118 insertions(+), 22 deletions(-)
>>>>>
>>
>><snipped>
>>
>>>>> diff --git a/test/tarantool-tests/misclib-memprof-lapi.test.lua b/test/tarantool-tests/misclib-memprof-lapi.test.lua
>>>>> index 3f4ffea0..b9edb80d 100644
>>>>> --- a/test/tarantool-tests/misclib-memprof-lapi.test.lua
>>>>> +++ b/test/tarantool-tests/misclib-memprof-lapi.test.lua
>>
>><snipped>
>>
>>>>> @@ -116,7 +120,8 @@ end
>>>>> local function check_alloc_report(alloc, traceno, line, function_line, nevents)
>>>>> local expected_name, event
>>>>> if traceno ~= 0 then
>>>>> - expected_name = string.format("TRACE [%d]", traceno)
>>>>> + expected_name = string.format("TRACE [%d] ", traceno)..
>>>>> + form_source_line(function_line)
>>>>
>>>>The output format differs from the one produced by memprof parser,
>>>>doesn't it?
>>>
>>>Yes, because we demangle names in <fill_ev_type> function. So, we can
>>>omit "started at" part to check that everything else is correct.
>>
>>Oh, I see... This is odd a bit but now I got it, thanks!
>>
>>>
>>
>><snipped>
>>
>>>>> diff --git a/tools/memprof/humanize.lua b/tools/memprof/humanize.lua
>>>>> index 7771005d..7d30f976 100644
>>>>> --- a/tools/memprof/humanize.lua
>>>>> +++ b/tools/memprof/humanize.lua
>>>>> @@ -7,6 +7,23 @@ local symtab = require "utils.symtab"
>>
>><snipped>
>>
>>>>> + -- recording started.
>>>>> + if trace and trace.addr == loc.addr then
>>>>> + return symtab.demangle(symbols, loc).." started at "..
>>>>> + symtab.demangle(symbols, trace.start)
>>>>
>>>>Finally, I got the thing that bothers me the most. Why do you make
>>>><describe_location> so complex? It looks that you can move all these
>>>>if-else branching to <symtab.demangle> and concatenation to
>>>><demangle_trace> function, doesn't it? AFAICS, you can remove
>>>><describe_location> as a result and trace demangling will be
>>>>encapsulated in scope of <demangle_trace> function. Feel free to correct
>>>>me if I'm wrong.
>>>
>>>Initially it was implemented, as you suggest now. But Sergey in his
>>>review led me to believe, that "started at" part should ideologically
>>>relate to the humanizer module. And I agree with that point, but maybe
>>>I decomposed things not in a very good way.
>>
>>Em... In that way all other types (such as "INTERNAL" and "CFUNC %#x")
>>should also be in the humanizer module, since this representation is
>>specific for a particular output format. All in all nobody stops you
>>from moving <symtab.demangle> to the humanize module, since it's used
>>only there (and need to be used only there).
>>
>>BTW, Sergey is also in Cc, so he can also drop a few words regarding it.
>>
>>>
>>>Another way to implement this is to demangle without "started at" and
>>>then insert it to the demangled name. What do you think?
>>
>>My point is to have the whole "stringification" mess encapsulated in a
>>single function (like it's almost done within <symtab.demangle>). And
>>the only thing remaining outside of this function is "started at" tail.
>>I hope this fits your vision regarding decomposition :)
>
>So, I decided to decompose things, as you suggested initially. Now
>traces are demangled separately inside the <demangle_trace> function.
>The "started at" string also moved to that function in order not to
>spout some convoluted logic of injecting this string inside the
>demangled string outside the demangler module. The only nuance is
>a possibility of recursion calls:
>
>| symtab.demangle -> demangle_trace -> symtab.demangle -> demangle_trace -> ...
>
>But I inserted asserts to prevent such cases.
>
>>
>>>
>>>>
>>>>> + end
>>>>> + return symtab.demangle(symbols, loc)
>>>>> +end
>>>>> +
>>
>><snipped>
>>
>>>>> --
>>>>> 2.33.0
>>>>>
>>>>
>>>>--
>>>>Best regards,
>>>>IM
>>>
>>>--
>>>Best regards,
>>>Mikhail Shishatskiy
>>
>>--
>>Best regards,
>>IM
>
>--
>Best regards,
>Mikhail Shishatskiy
More information about the Tarantool-patches
mailing list