From: Mike Pall <mike> Thanks to Julien Desgats. (cherry picked from commit 92fa45f9eb5d9aa732c6b972a85c26120d7612b4) Embedded LuaJIT profiler uses the following approach: * Create trigger on timer signals, which set `HOOK_PROFILE` flag on `g->hookmask` (if not set already) and update all BC instructions dispatch. * When any of instruction is executed, callback set by user on profiler initialize is called. After the dispatch table updated again to the old static values, and flags are reset. * `HOOK_PROFILE` flag will set again and dispatch will updated at the next tick of the timer. Before call to __gc finalizer the old hookmask is saved to be restored later. When the second step is happening on call of __gc metamethod `HOOK_PROFILE` flag is reset. But right after that the old hook disposition (with `HOOK_PROFILE`) is restored, when we leaving `gc_call_finalizer()` without updating the dispatch table, so the profiler callback is never called again. This patch updates dispatch table right after hooks manipulation in `gc_call_finalizer()` and prevent ticks influence inside finalizer calls. Sergey Kaplun: * added the description and the test for the problem Part of tarantool/tarantool#6548 --- Side note: PR has 2 extra commits because the tarantool/luajit master (tarantool branch) isn't bumped in the tarantool yet. Branch: https://github.com/tarantool/luajit/tree/skaplun/lj-512-profiler-hook-finalizers-full-ci Tarantool PR: https://github.com/tarantool/tarantool/pull/7237 Related issues: * https://github.com/LuaJIT/LuaJIT/issues/512 * https://github.com/tarantool/tarantool/issues/6548 src/lj_gc.c | 2 ++ src/lj_obj.h | 3 +- src/lj_profile.c | 2 +- .../lj-512-profiler-hook-finalizers.test.lua | 31 +++++++++++++++++++ 4 files changed, 36 insertions(+), 2 deletions(-) create mode 100644 test/tarantool-tests/lj-512-profiler-hook-finalizers.test.lua diff --git a/src/lj_gc.c b/src/lj_gc.c index 7f0ec896..29387a48 100644 --- a/src/lj_gc.c +++ b/src/lj_gc.c @@ -493,6 +493,7 @@ static void gc_call_finalizer(global_State *g, lua_State *L, TValue *top; lj_trace_abort(g); hook_entergc(g); /* Disable hooks and new traces during __gc. */ + if (LJ_HASPROFILE && (oldh & HOOK_PROFILE)) lj_dispatch_update(g); g->gc.threshold = LJ_MAX_MEM; /* Prevent GC steps. */ top = L->top; copyTV(L, top++, mo); @@ -501,6 +502,7 @@ static void gc_call_finalizer(global_State *g, lua_State *L, L->top = top+1; errcode = lj_vm_pcall(L, top, 1+0, -1); /* Stack: |mo|o| -> | */ hook_restore(g, oldh); + if (LJ_HASPROFILE && (oldh & HOOK_PROFILE)) lj_dispatch_update(g); g->gc.threshold = oldt; /* Restore GC threshold. */ if (errcode) lj_err_throw(L, errcode); /* Propagate errors. */ diff --git a/src/lj_obj.h b/src/lj_obj.h index 197d735a..d1451c3a 100644 --- a/src/lj_obj.h +++ b/src/lj_obj.h @@ -692,7 +692,8 @@ typedef struct global_State { #define HOOK_PROFILE 0x80 #define hook_active(g) ((g)->hookmask & HOOK_ACTIVE) #define hook_enter(g) ((g)->hookmask |= HOOK_ACTIVE) -#define hook_entergc(g) ((g)->hookmask |= (HOOK_ACTIVE|HOOK_GC)) +#define hook_entergc(g) \ + ((g)->hookmask = ((g)->hookmask | (HOOK_ACTIVE|HOOK_GC)) & ~HOOK_PROFILE) #define hook_vmevent(g) ((g)->hookmask |= (HOOK_ACTIVE|HOOK_VMEVENT)) #define hook_leave(g) ((g)->hookmask &= ~HOOK_ACTIVE) #define hook_save(g) ((g)->hookmask & ~HOOK_EVENTMASK) diff --git a/src/lj_profile.c b/src/lj_profile.c index 4412d68b..896d8f46 100644 --- a/src/lj_profile.c +++ b/src/lj_profile.c @@ -106,7 +106,7 @@ static void profile_trigger(ProfileState *ps) profile_lock(ps); ps->samples++; /* Always increment number of samples. */ mask = g->hookmask; - if (!(mask & (HOOK_PROFILE|HOOK_VMEVENT))) { /* Set profile hook. */ + if (!(mask & (HOOK_PROFILE|HOOK_VMEVENT|HOOK_GC))) { /* Set profile hook. */ int st = g->vmstate; ps->vmstate = st >= 0 ? 'N' : st == ~LJ_VMST_INTERP ? 'I' : diff --git a/test/tarantool-tests/lj-512-profiler-hook-finalizers.test.lua b/test/tarantool-tests/lj-512-profiler-hook-finalizers.test.lua new file mode 100644 index 00000000..4b6aabb7 --- /dev/null +++ b/test/tarantool-tests/lj-512-profiler-hook-finalizers.test.lua @@ -0,0 +1,31 @@ +local tap = require('tap') +local profile = require('jit.profile') + +local test = tap.test('lj-512-profiler-hook-finalizers') +test:plan(1) + +-- Sampling interval in ms. +local INTERVAL = 10 + +local nsamples = 0 +profile.start('li' .. tostring(INTERVAL), function() + nsamples = nsamples + 1 +end) + +local start = os.clock() +for _ = 1, 1e6 do + getmetatable(newproxy(true)).__gc = function() end +end +local finish = os.clock() + +profile.stop() + +-- XXX: The bug is occured as stopping of callbacks invocation, +-- when a new tick strikes inside `gc_call_finalizer()`. +-- The amount of successfull callbacks isn't stable (2-15). +-- So, assume that amount of profiling samples should be at least +-- more than 0.5 intervals of time during sampling. +test:ok(nsamples >= 0.5 * (finish - start) * 1e3 / INTERVAL, + 'profiler sampling') + +os.exit(test:check() and 0 or 1) -- 2.34.1
Hi! Thanks for the patch! LGTM with minor updates to the message. Sergos > On 6 Jun 2022, at 16:35, Sergey Kaplun <skaplun@tarantool.org> wrote: > > From: Mike Pall <mike> > > Thanks to Julien Desgats. > > (cherry picked from commit 92fa45f9eb5d9aa732c6b972a85c26120d7612b4) > > Embedded LuaJIT profiler uses the following approach: > * Create trigger on timer signals, which set `HOOK_PROFILE` flag on > `g->hookmask` (if not set already) and update all BC instructions > dispatch. ??? plural, perhaps dispatch places? > * When any of instruction is executed, callback set by user on profiler a > initialize is called. After the dispatch table updated again to > the old static values, and flags are reset. > * `HOOK_PROFILE` flag will set again and dispatch will updated at the next > tick of the timer. > > Before call to __gc finalizer the old hookmask is saved to be restored a for the future use. > later. When the second step is happening on call of __gc metamethod a a > `HOOK_PROFILE` flag is reset. But right after that the old hook the > disposition (with `HOOK_PROFILE`) is restored, when we leaving > `gc_call_finalizer()` without updating the dispatch table, so the > profiler callback is never called again. > > This patch updates dispatch table right after hooks manipulation in > `gc_call_finalizer()` and prevent ticks influence inside finalizer > calls. > > Sergey Kaplun: > * added the description and the test for the problem > > Part of tarantool/tarantool#6548 > --- > > Side note: PR has 2 extra commits because the tarantool/luajit master > (tarantool branch) isn't bumped in the tarantool yet. > > Branch: https://github.com/tarantool/luajit/tree/skaplun/lj-512-profiler-hook-finalizers-full-ci > Tarantool PR: https://github.com/tarantool/tarantool/pull/7237 > Related issues: > * https://github.com/LuaJIT/LuaJIT/issues/512 > * https://github.com/tarantool/tarantool/issues/6548 > > > src/lj_gc.c | 2 ++ > src/lj_obj.h | 3 +- > src/lj_profile.c | 2 +- > .../lj-512-profiler-hook-finalizers.test.lua | 31 +++++++++++++++++++ > 4 files changed, 36 insertions(+), 2 deletions(-) > create mode 100644 test/tarantool-tests/lj-512-profiler-hook-finalizers.test.lua > > diff --git a/src/lj_gc.c b/src/lj_gc.c > index 7f0ec896..29387a48 100644 > --- a/src/lj_gc.c > +++ b/src/lj_gc.c > @@ -493,6 +493,7 @@ static void gc_call_finalizer(global_State *g, lua_State *L, > TValue *top; > lj_trace_abort(g); > hook_entergc(g); /* Disable hooks and new traces during __gc. */ > + if (LJ_HASPROFILE && (oldh & HOOK_PROFILE)) lj_dispatch_update(g); > g->gc.threshold = LJ_MAX_MEM; /* Prevent GC steps. */ > top = L->top; > copyTV(L, top++, mo); > @@ -501,6 +502,7 @@ static void gc_call_finalizer(global_State *g, lua_State *L, > L->top = top+1; > errcode = lj_vm_pcall(L, top, 1+0, -1); /* Stack: |mo|o| -> | */ > hook_restore(g, oldh); > + if (LJ_HASPROFILE && (oldh & HOOK_PROFILE)) lj_dispatch_update(g); > g->gc.threshold = oldt; /* Restore GC threshold. */ > if (errcode) > lj_err_throw(L, errcode); /* Propagate errors. */ > diff --git a/src/lj_obj.h b/src/lj_obj.h > index 197d735a..d1451c3a 100644 > --- a/src/lj_obj.h > +++ b/src/lj_obj.h > @@ -692,7 +692,8 @@ typedef struct global_State { > #define HOOK_PROFILE 0x80 > #define hook_active(g) ((g)->hookmask & HOOK_ACTIVE) > #define hook_enter(g) ((g)->hookmask |= HOOK_ACTIVE) > -#define hook_entergc(g) ((g)->hookmask |= (HOOK_ACTIVE|HOOK_GC)) > +#define hook_entergc(g) \ > + ((g)->hookmask = ((g)->hookmask | (HOOK_ACTIVE|HOOK_GC)) & ~HOOK_PROFILE) > #define hook_vmevent(g) ((g)->hookmask |= (HOOK_ACTIVE|HOOK_VMEVENT)) > #define hook_leave(g) ((g)->hookmask &= ~HOOK_ACTIVE) > #define hook_save(g) ((g)->hookmask & ~HOOK_EVENTMASK) > diff --git a/src/lj_profile.c b/src/lj_profile.c > index 4412d68b..896d8f46 100644 > --- a/src/lj_profile.c > +++ b/src/lj_profile.c > @@ -106,7 +106,7 @@ static void profile_trigger(ProfileState *ps) > profile_lock(ps); > ps->samples++; /* Always increment number of samples. */ > mask = g->hookmask; > - if (!(mask & (HOOK_PROFILE|HOOK_VMEVENT))) { /* Set profile hook. */ > + if (!(mask & (HOOK_PROFILE|HOOK_VMEVENT|HOOK_GC))) { /* Set profile hook. */ > int st = g->vmstate; > ps->vmstate = st >= 0 ? 'N' : > st == ~LJ_VMST_INTERP ? 'I' : > diff --git a/test/tarantool-tests/lj-512-profiler-hook-finalizers.test.lua b/test/tarantool-tests/lj-512-profiler-hook-finalizers.test.lua > new file mode 100644 > index 00000000..4b6aabb7 > --- /dev/null > +++ b/test/tarantool-tests/lj-512-profiler-hook-finalizers.test.lua > @@ -0,0 +1,31 @@ > +local tap = require('tap') > +local profile = require('jit.profile') > + > +local test = tap.test('lj-512-profiler-hook-finalizers') > +test:plan(1) > + > +-- Sampling interval in ms. > +local INTERVAL = 10 > + > +local nsamples = 0 > +profile.start('li' .. tostring(INTERVAL), function() > + nsamples = nsamples + 1 > +end) > + > +local start = os.clock() > +for _ = 1, 1e6 do > + getmetatable(newproxy(true)).__gc = function() end > +end > +local finish = os.clock() > + > +profile.stop() > + > +-- XXX: The bug is occured as stopping of callbacks invocation, > +-- when a new tick strikes inside `gc_call_finalizer()`. > +-- The amount of successfull callbacks isn't stable (2-15). > +-- So, assume that amount of profiling samples should be at least > +-- more than 0.5 intervals of time during sampling. > +test:ok(nsamples >= 0.5 * (finish - start) * 1e3 / INTERVAL, > + 'profiler sampling') > + > +os.exit(test:check() and 0 or 1) > -- > 2.34.1 >
Sergey, Thanks for the patch! LGTM, with the fixes for the nits left by Sergos. -- Best regards, IM
Sergey, I've checked the patch into all long-term branches in tarantool/luajit and bumped a new version in master, 2.10 and 1.10. On 06.06.22, Sergey Kaplun wrote: > From: Mike Pall <mike> > > Thanks to Julien Desgats. > > (cherry picked from commit 92fa45f9eb5d9aa732c6b972a85c26120d7612b4) > > Embedded LuaJIT profiler uses the following approach: > * Create trigger on timer signals, which set `HOOK_PROFILE` flag on > `g->hookmask` (if not set already) and update all BC instructions > dispatch. > * When any of instruction is executed, callback set by user on profiler > initialize is called. After the dispatch table updated again to > the old static values, and flags are reset. > * `HOOK_PROFILE` flag will set again and dispatch will updated at the next > tick of the timer. > > Before call to __gc finalizer the old hookmask is saved to be restored > later. When the second step is happening on call of __gc metamethod > `HOOK_PROFILE` flag is reset. But right after that the old hook > disposition (with `HOOK_PROFILE`) is restored, when we leaving > `gc_call_finalizer()` without updating the dispatch table, so the > profiler callback is never called again. > > This patch updates dispatch table right after hooks manipulation in > `gc_call_finalizer()` and prevent ticks influence inside finalizer > calls. > > Sergey Kaplun: > * added the description and the test for the problem > > Part of tarantool/tarantool#6548 > --- > > Side note: PR has 2 extra commits because the tarantool/luajit master > (tarantool branch) isn't bumped in the tarantool yet. > > Branch: https://github.com/tarantool/luajit/tree/skaplun/lj-512-profiler-hook-finalizers-full-ci > Tarantool PR: https://github.com/tarantool/tarantool/pull/7237 > Related issues: > * https://github.com/LuaJIT/LuaJIT/issues/512 > * https://github.com/tarantool/tarantool/issues/6548 > > > src/lj_gc.c | 2 ++ > src/lj_obj.h | 3 +- > src/lj_profile.c | 2 +- > .../lj-512-profiler-hook-finalizers.test.lua | 31 +++++++++++++++++++ > 4 files changed, 36 insertions(+), 2 deletions(-) > create mode 100644 test/tarantool-tests/lj-512-profiler-hook-finalizers.test.lua > <snipped> > -- > 2.34.1 > -- Best regards, IM