Re: [Tarantool-patches] [PATCH luajit v4 4/4] memprof: add info about trace start to symtab

[Mikhail Shishatskiy via Tarantool-patches <tarantool-patches@dev.tarantool.org>]

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