From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from [87.239.111.99] (localhost [127.0.0.1]) by dev.tarantool.org (Postfix) with ESMTP id 560CF6ECE3; Mon, 22 Nov 2021 18:11:24 +0300 (MSK) DKIM-Filter: OpenDKIM Filter v2.11.0 dev.tarantool.org 560CF6ECE3 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=tarantool.org; s=dev; t=1637593884; bh=FT7+OVCBDFatagm14DerLN0fIRW/vFBE+sqNCVB4yT4=; h=Date:To:References:In-Reply-To:Subject:List-Id:List-Unsubscribe: List-Archive:List-Post:List-Help:List-Subscribe:From:Reply-To:Cc: From; b=XKS4FKfp/9ArK2vz3WgUfN4CPq4eugNrTJshKlHtaeuh5lcU1osB0tmgc7KE/6Fk+ Tbod/0Y6P3B0RPmFn8GMKQ4f8/jiwWs1W/88PWg0+DdWe6Wb6WjcISEz1evbnyNGjX 4EcGZwbI+8i4OvdO/z8A4Bu5fduMzX7WwQ4uHdfs= Received: from smtp17.mail.ru (smtp17.mail.ru [94.100.176.154]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dev.tarantool.org (Postfix) with ESMTPS id 942FC6ECE3 for ; Mon, 22 Nov 2021 18:11:22 +0300 (MSK) DKIM-Filter: OpenDKIM Filter v2.11.0 dev.tarantool.org 942FC6ECE3 Received: by smtp17.mail.ru with esmtpa (envelope-from ) id 1mpAyX-0007hE-GX; Mon, 22 Nov 2021 18:11:22 +0300 Date: Mon, 22 Nov 2021 18:11:19 +0300 To: Igor Munkin Message-ID: <20211122151119.ilbfcxcux4kpzrqy@surf.localdomain> References: <20210929200758.149446-1-m.shishatskiy@tarantool.org> <20210929200758.149446-5-m.shishatskiy@tarantool.org> <20211101163113.GE8831@tarantool.org> <20211104130228.x6qcne5xeh544hm7@surf.localdomain> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8; format=flowed Content-Disposition: inline In-Reply-To: X-4EC0790: 10 X-7564579A: 646B95376F6C166E X-77F55803: 4F1203BC0FB41BD9FE0487E5024681462F7D4F1224D5FC4DEE0E8ED8BE98D659182A05F53808504064315BA502577973DC2020F6F0FD5C74F866EE6A2C8B27D56FCCD786B7F5C975 X-7FA49CB5: FF5795518A3D127A4AD6D5ED66289B5278DA827A17800CE7922D113DFDC6D5A3EA1F7E6F0F101C67BD4B6F7A4D31EC0BCC500DACC3FED6E28638F802B75D45FF8AA50765F7900637A9545EB8D2325CAFEA1F7E6F0F101C6723150C8DA25C47586E58E00D9D99D84E1BDDB23E98D2D38BBCA57AF85F7723F2F9EBB953EB96EB53331D62FA79235C9ACC7F00164DA146DAFE8445B8C89999728AA50765F7900637F6B57BC7E64490618DEB871D839B7333395957E7521B51C2DFABB839C843B9C08941B15DA834481F8AA50765F7900637F6B57BC7E6449061A352F6E88A58FB86F5D81C698A659EA73AA81AA40904B5D9A18204E546F3947C893991AD1F2BFC6A040F9FF01DFDA4A84AD6D5ED66289B52698AB9A7B718F8C46E0066C2D8992A16725E5C173C3A84C3091AF3C34090AE74BA3038C0950A5D36B5C8C57E37DE458B0BC6067A898B09E46D1867E19FE14079C09775C1D3CA48CF3D321E7403792E342EB15956EA79C166A417C69337E82CC275ECD9A6C639B01B78DA827A17800CE728E0B16DA17939D7731C566533BA786AA5CC5B56E945C8DA X-C1DE0DAB: 0D63561A33F958A5351ACEC1639A8B2972457491BF518D8BF6507D71D44BBCB0D59269BC5F550898D99A6476B3ADF6B47008B74DF8BB9EF7333BD3B22AA88B938A852937E12ACA759F66ED85EB5F25FD410CA545F18667F91A7EA1CDA0B5A7A0 X-C8649E89: 4E36BF7865823D7055A7F0CF078B5EC49A30900B95165D34BC3EEE75EF3BACCF3527F1ED975EA9499DD529771A678CF921A56D3AE728D153F79159214299D6D51D7E09C32AA3244CAEDBBB41FBE98616F678BB73CFBC6C0830452B15D76AEC14FACE5A9C96DEB163 X-D57D3AED: 3ZO7eAau8CL7WIMRKs4sN3D3tLDjz0dLbV79QFUyzQ2Ujvy7cMT6pYYqY16iZVKkSc3dCLJ7zSJH7+u4VD18S7Vl4ZUrpaVfd2+vE6kuoey4m4VkSEu530nj6fImhcD4MUrOEAnl0W826KZ9Q+tr5ycPtXkTV4k65bRjmOUUP8cvGozZ33TWg5HZplvhhXbhDGzqmQDTd6OAevLeAnq3Ra9uf7zvY2zzsIhlcp/Y7m53TZgf2aB4JOg4gkr2biojp2KOOpFlmzeMdhA+VRwQug== X-Mailru-Sender: EFA0F3A8419EF21635BFE795C6CB22C970998F39102592EFDC2020F6F0FD5C748FF8BC079CCEBBDC2376072A51849BFFE66B5C1DBFD5D09D5E022D45988A037B448E0EA96F20AB367402F9BA4338D657ED14614B50AE0675 X-Mras: Ok Subject: Re: [Tarantool-patches] [PATCH luajit v4 4/4] memprof: add info about trace start to symtab X-BeenThere: tarantool-patches@dev.tarantool.org X-Mailman-Version: 2.1.34 Precedence: list List-Id: Tarantool development patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , From: Mikhail Shishatskiy via Tarantool-patches Reply-To: Mikhail Shishatskiy Cc: tarantool-patches@dev.tarantool.org Errors-To: tarantool-patches-bounces@dev.tarantool.org Sender: "Tarantool-patches" 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 [] 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 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 := | trace-addr := The memory profiler parser is adjusted to recognize the entries mentioned above. On top of that, the API of 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 , and one will get an output in the format + described below: | TRACE [] started at @: 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 is the same as the one - -- yielded from the fucntion + -- yielded from the function -- in the 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 [] >> >> 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 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 := >> | trace-addr := >> >> The memory profiler parser is adjusted to recognize the entries >> mentioned above. On top of that, the API of 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 module, >> which allows one to get a description of the trace location in the >> format described below: >> >> | TRACE [] started at @: >> >> 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 >> - )) >> + 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 is the same as the one >> + -- yielded from the fucntion > >Typo: s/fucntion/function/. > >> + -- in the 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 >> >> >> >> >> >> >> | TRACE [] >> >> >> >> 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 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 := >> >> | trace-addr := >> >> >> >> The memory profiler parser is adjusted to recognize the entries >> >> mentioned above. On top of that, the API of 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 module, >> >> which allows one to get a description of the trace location in the >> >> format described below: >> >> >> >> | TRACE [] started at @: >> >> >> >> 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(-) >> >> > > > >> >> 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 > > > >> >> @@ -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 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! > >> > > > >> >> 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" > > > >> >> + -- 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 >> > so complex? It looks that you can move all these >> >if-else branching to and concatenation to >> > function, doesn't it? AFAICS, you can remove >> > as a result and trace demangling will be >> >encapsulated in scope of 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 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 ). 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 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 >> >> + > > > >> >> -- >> >> 2.33.0 >> >> >> > >> >-- >> >Best regards, >> >IM >> >> -- >> Best regards, >> Mikhail Shishatskiy > >-- >Best regards, >IM -- Best regards, Mikhail Shishatskiy