[Tarantool-patches] [PATCH luajit] Fix interaction between profiler hooks and finalizers.

[Tarantool-patches] [PATCH luajit] Fix interaction between profiler hooks and finalizers.

[Sergey Kaplun via Tarantool-patches]

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

Re: [Tarantool-patches] [PATCH luajit] Fix interaction between profiler hooks and finalizers.

[sergos via Tarantool-patches]

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
> 

Re: [Tarantool-patches] [PATCH luajit] Fix interaction between profiler hooks and finalizers.

[Igor Munkin via Tarantool-patches]

Sergey,

Thanks for the patch! LGTM, with the fixes for the nits left by Sergos.

-- 
Best regards,
IM

Re: [Tarantool-patches] [PATCH luajit] Fix interaction between profiler hooks and finalizers.

[Igor Munkin via Tarantool-patches]

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