[tarantool-patches] [PATCH v2 0/3] Dump lua frames for a fiber traceback

[tarantool-patches] [PATCH v2 0/3] Dump lua frames for a fiber traceback

[Georgy Kirichenko]

Lua frames are now dumped as well as plain C-frames for a
fiber backtrace. The main patch follows two preparation fixes:
 - enable backtrace for an active coroutine;
 - setup lua state for the main fiber;

Georgy Kirichenko (3):
  fiber: do not inline coro unwind function
  Proper unwind for currently executing fiber
  Show names of Lua functions in backtraces

 src/backtrace.cc        | 27 ++++++++++++-
 src/lua/fiber.c         | 86 +++++++++++++++++++++++++++++++++++------
 test/app/fiber.result   | 33 ++++++++++++++++
 test/app/fiber.test.lua | 12 ++++++
 4 files changed, 146 insertions(+), 12 deletions(-)

-- 
2.19.1

https://github.com/tarantool/tarantool/issues/3538
https://github.com/tarantool/tarantool/compare/g.kirichenko/gh-3538-lua-backtrace

Changes in v2:
 - Rebased against the latest 1.10
 - Segmentation fault fixed

[tarantool-patches] [PATCH 1/3] fiber: do not inline coro unwind function

[Georgy Kirichenko]

Call coro_unwcontext via function pointer to protect the
function from inlining.
---
 src/backtrace.cc | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/src/backtrace.cc b/src/backtrace.cc
index 2512bc045..66dcc0047 100644
--- a/src/backtrace.cc
+++ b/src/backtrace.cc
@@ -363,12 +363,17 @@ __asm__ volatile(
 #endif
 }
 
+typedef void (*coro_unwcontext_indirect_f)(unw_context_t *unw_context,
+					   struct coro_context *coro_ctx);
+/* Variable to process coro_unwcontext indirect call to avoid inlining. */
+static volatile coro_unwcontext_indirect_f coro_unwcontext_indirect = coro_unwcontext;
+
 void
 backtrace_foreach(backtrace_cb cb, coro_context *coro_ctx, void *cb_ctx)
 {
 	unw_cursor_t unw_cur;
 	unw_context_t unw_ctx;
-	coro_unwcontext(&unw_ctx, coro_ctx);
+	coro_unwcontext_indirect(&unw_ctx, coro_ctx);
 	unw_init_local(&unw_cur, &unw_ctx);
 	int frame_no = 0;
 	unw_word_t sp = 0, old_sp = 0, ip, offset;
-- 
2.19.1

Re: [tarantool-patches] [PATCH 1/3] fiber: do not inline coro unwind function

[Vladimir Davydov]

On Wed, Oct 10, 2018 at 07:39:24PM +0300, Georgy Kirichenko wrote:
> Call coro_unwcontext via function pointer to protect the
> function from inlining.
> ---
>  src/backtrace.cc | 7 ++++++-
>  1 file changed, 6 insertions(+), 1 deletion(-)
> 
> diff --git a/src/backtrace.cc b/src/backtrace.cc
> index 2512bc045..66dcc0047 100644
> --- a/src/backtrace.cc
> +++ b/src/backtrace.cc
> @@ -363,12 +363,17 @@ __asm__ volatile(
>  #endif
>  }
>  
> +typedef void (*coro_unwcontext_indirect_f)(unw_context_t *unw_context,
> +					   struct coro_context *coro_ctx);
> +/* Variable to process coro_unwcontext indirect call to avoid inlining. */
> +static volatile coro_unwcontext_indirect_f coro_unwcontext_indirect = coro_unwcontext;
> +

Why must not it be inlined? I think it deserves an explanation in
the comment.

Also, may be we'd better use NOINLINE attribute instead of function
pointer?

>  void
>  backtrace_foreach(backtrace_cb cb, coro_context *coro_ctx, void *cb_ctx)
>  {
>  	unw_cursor_t unw_cur;
>  	unw_context_t unw_ctx;
> -	coro_unwcontext(&unw_ctx, coro_ctx);
> +	coro_unwcontext_indirect(&unw_ctx, coro_ctx);
>  	unw_init_local(&unw_cur, &unw_ctx);
>  	int frame_no = 0;
>  	unw_word_t sp = 0, old_sp = 0, ip, offset;

[tarantool-patches] [PATCH 2/3] Proper unwind for currently executing fiber

[Georgy Kirichenko]

Each yielded fiber has a preserved coro state stored in a corresponding
variable however an executing fiber has a volatile state placed in CPU
registers (stack pointer, instruction pointer and non-volatile registers)
and corresponding context-storing variable value is invalid.
For already yielded fiber we have to use a special asm-written handler to make
a temporary switch to the preserved state and capture executing context what
is not needed for executing fiber.
After the patch for the executing fiber NULL is passed to the backtrace
function as coro context and then backtrace function could decide should
it use special context-switching handler or might just use unw_getcontext
from the unwind library.
---
 src/backtrace.cc | 22 +++++++++++++++++++++-
 1 file changed, 21 insertions(+), 1 deletion(-)

diff --git a/src/backtrace.cc b/src/backtrace.cc
index 66dcc0047..51e8b54da 100644
--- a/src/backtrace.cc
+++ b/src/backtrace.cc
@@ -368,12 +368,32 @@ typedef void (*coro_unwcontext_indirect_f)(unw_context_t *unw_context,
 /* Variable to process coro_unwcontext indirect call to avoid inlining. */
 static volatile coro_unwcontext_indirect_f coro_unwcontext_indirect = coro_unwcontext;
 
+/*
+ * Call `cb' callback for each `coro_ctx' contained frame or the current
+ * executed coroutine if `coro_ctx' is NULL. A coro_context is a structure
+ * created on each coroutine yield to store execution context so for an on-CPU
+ * coroutine there is no valid coro_context could be defined and NULL is
+ * passed.
+*/
 void
 backtrace_foreach(backtrace_cb cb, coro_context *coro_ctx, void *cb_ctx)
 {
 	unw_cursor_t unw_cur;
 	unw_context_t unw_ctx;
-	coro_unwcontext_indirect(&unw_ctx, coro_ctx);
+	if (coro_ctx == NULL) {
+		/*
+		 * Current executing coroutine and simple unw_getcontext
+		 * should function.
+		 */
+		unw_getcontext(&unw_ctx);
+	} else {
+		/*
+		 * Execution context is stored in the coro_ctx
+		 * so use special context-switching handler to
+		 * capture an unwind context.
+		 */
+		coro_unwcontext_indirect(&unw_ctx, coro_ctx);
+	}
 	unw_init_local(&unw_cur, &unw_ctx);
 	int frame_no = 0;
 	unw_word_t sp = 0, old_sp = 0, ip, offset;
-- 
2.19.1

[tarantool-patches] [PATCH 3/3] Show names of Lua functions in backtraces

[Georgy Kirichenko]

Trace corresponding Lua state as well as normal C stack frames while
fiber backtracing. This might be useful for debugging purposes.

Fixes: #3538
---
 src/lua/fiber.c         | 86 +++++++++++++++++++++++++++++++++++------
 test/app/fiber.result   | 33 ++++++++++++++++
 test/app/fiber.test.lua | 12 ++++++
 3 files changed, 120 insertions(+), 11 deletions(-)

diff --git a/src/lua/fiber.c b/src/lua/fiber.c
index 147add89b..428c2f938 100644
--- a/src/lua/fiber.c
+++ b/src/lua/fiber.c
@@ -178,20 +178,79 @@ lbox_fiber_id(struct lua_State *L)
 	return 1;
 }
 
+/**
+ * Lua fiber traceback context.
+ */
+struct lua_fiber_tb_ctx {
+	/* Lua stack to push values. */
+	struct lua_State *L;
+	/* Lua stack to trace. */
+	struct lua_State *R;
+	/* Current Lua frame. */
+	int lua_frame;
+	/* Count of traced frames (both C and Lua). */
+	int tb_frame;
+};
+
 #ifdef ENABLE_BACKTRACE
-static int
-fiber_backtrace_cb(int frameno, void *frameret, const char *func, size_t offset, void *cb_ctx)
+static void
+dump_lua_frame(struct lua_State *L, lua_Debug *ar, int tb_frame, int lua_frame)
 {
 	char buf[512];
-	int l = snprintf(buf, sizeof(buf), "#%-2d %p in ", frameno, frameret);
-	if (func)
-		snprintf(buf + l, sizeof(buf) - l, "%s+%zu", func, offset);
-	else
-		snprintf(buf + l, sizeof(buf) - l, "?");
-	struct lua_State *L = (struct lua_State*)cb_ctx;
-	lua_pushnumber(L, frameno + 1);
+	snprintf(buf, sizeof(buf), "LUA#%-2d %s in %s at line %i",
+		 lua_frame + 1,
+		 ar->name != NULL ? ar->name : "(unnamed)",
+		 ar->source, ar->currentline);
+	lua_pushnumber(L, tb_frame);
 	lua_pushstring(L, buf);
 	lua_settable(L, -3);
+}
+
+static int
+fiber_backtrace_cb(int frameno, void *frameret, const char *func, size_t offset, void *cb_ctx)
+{
+	struct lua_fiber_tb_ctx *tb_ctx = (struct lua_fiber_tb_ctx *)cb_ctx;
+	struct lua_State *L = tb_ctx->L;
+	if (strstr(func, "lj_BC_FUNCC") == func) {
+		/* We are in the LUA vm. */
+		lua_Debug ar;
+		while (tb_ctx->R && lua_getstack(tb_ctx->R, tb_ctx->lua_frame, &ar) > 0) {
+			/* Skip all following C-frames. */
+			lua_getinfo(tb_ctx->R, "Sln", &ar);
+			if (*ar.what != 'C')
+				break;
+			if (ar.name != NULL) {
+				/* Dump frame if it is a C built-in call. */
+				tb_ctx->tb_frame++;
+				dump_lua_frame(L, &ar, tb_ctx->tb_frame,
+					       tb_ctx->lua_frame);
+			}
+			tb_ctx->lua_frame++;
+		}
+		while (tb_ctx->R && lua_getstack(tb_ctx->R, tb_ctx->lua_frame, &ar) > 0) {
+			/* Trace Lua frame. */
+			lua_getinfo(tb_ctx->R, "Sln", &ar);
+			if (*ar.what == 'C') {
+				break;
+			}
+			tb_ctx->tb_frame++;
+			dump_lua_frame(L, &ar, tb_ctx->tb_frame,
+				       tb_ctx->lua_frame);
+			tb_ctx->lua_frame++;
+		}
+	} else {
+		char buf[512];
+		int l = snprintf(buf, sizeof(buf), "#%-2d %p in ",
+				 frameno + 1, frameret);
+		if (func)
+			snprintf(buf + l, sizeof(buf) - l, "%s+%zu", func, offset);
+		else
+			snprintf(buf + l, sizeof(buf) - l, "?");
+		tb_ctx->tb_frame++;
+		lua_pushnumber(L, tb_ctx->tb_frame);
+		lua_pushstring(L, buf);
+		lua_settable(L, -3);
+	}
 	return 0;
 }
 #endif
@@ -229,10 +288,15 @@ lbox_fiber_statof(struct fiber *f, void *cb_ctx, bool backtrace)
 
 	if (backtrace) {
 #ifdef ENABLE_BACKTRACE
+		struct lua_fiber_tb_ctx tb_ctx;
+		tb_ctx.L = L;
+		tb_ctx.R = f->storage.lua.stack;
+		tb_ctx.lua_frame = 0;
+		tb_ctx.tb_frame = 0;
 		lua_pushstring(L, "backtrace");
 		lua_newtable(L);
-		if (f != fiber())
-			backtrace_foreach(fiber_backtrace_cb, &f->ctx, L);
+		backtrace_foreach(fiber_backtrace_cb,
+				  f != fiber() ? &f->ctx : NULL, &tb_ctx);
 		lua_settable(L, -3);
 #endif /* ENABLE_BACKTRACE */
 	}
diff --git a/test/app/fiber.result b/test/app/fiber.result
index 77144e661..1a7827fa1 100644
--- a/test/app/fiber.result
+++ b/test/app/fiber.result
@@ -849,6 +849,39 @@ f2:cancel()
 f3:cancel()
 ---
 ...
+function sf1() loop() end
+---
+...
+function sf2() sf1() end
+---
+...
+function sf3() sf2() end
+---
+...
+f1 = fiber.create(sf3)
+---
+...
+info = fiber.info()
+---
+...
+backtrace = info[f1:id()].backtrace
+---
+...
+bt_str = table.concat(backtrace, '\n')
+---
+...
+bt_str:find('sf1') ~= nil
+---
+- true
+...
+bt_str:find('loop') ~= nil
+---
+- true
+...
+bt_str:find('sf3') ~= nil
+---
+- true
+...
 -- # gh-666: nulls in output
 --
 getmetatable(fiber.info())
diff --git a/test/app/fiber.test.lua b/test/app/fiber.test.lua
index 98a136090..9df751cc8 100644
--- a/test/app/fiber.test.lua
+++ b/test/app/fiber.test.lua
@@ -334,6 +334,18 @@ f1:cancel()
 f2:cancel()
 f3:cancel()
 
+function sf1() loop() end
+function sf2() sf1() end
+function sf3() sf2() end
+f1 = fiber.create(sf3)
+
+info = fiber.info()
+backtrace = info[f1:id()].backtrace
+bt_str = table.concat(backtrace, '\n')
+bt_str:find('sf1') ~= nil
+bt_str:find('loop') ~= nil
+bt_str:find('sf3') ~= nil
+
 -- # gh-666: nulls in output
 --
 getmetatable(fiber.info())
-- 
2.19.1

[tarantool-patches] [PATCH 0/3] Dump lua frames for a fiber traceback

[Georgy Kirichenko]

Lua frames are now dumped as well as plain C-frames for a
fiber backtrace. The main patch follows two preparation fixes:
 - enable backtrace for an active coroutine;
 - setup lua state for the main fiber;

Issue: https://github.com/tarantool/tarantool/issues/3538
Branch:
https://github.com/tarantool/tarantool/compare/g.kirichenko/gh-3538-lua-backtrace

Georgy Kirichenko (3):
  Set a lua state for the main fiber too
  Proper unwind for currently executing fiber
  Show names of Lua functions in backtraces

 src/backtrace.cc        |  5 ++-
 src/lua/fiber.c         | 86 +++++++++++++++++++++++++++++++++++------
 src/lua/init.c          |  1 +
 test/app/fiber.result   | 33 ++++++++++++++++
 test/app/fiber.test.lua | 12 ++++++
 5 files changed, 125 insertions(+), 12 deletions(-)

-- 
2.19.0

[tarantool-patches] [PATCH 2/3] Proper unwind for currently executing fiber

[Georgy Kirichenko]

A fiber's coro context stores execution state for a corresponding
already yielded fiber. If fiber is on the execution then it hasn't
valid stored coro state and might be backtraced without a special unwind
context builder.
---
 src/backtrace.cc | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/src/backtrace.cc b/src/backtrace.cc
index 2512bc045..70ed913e0 100644
--- a/src/backtrace.cc
+++ b/src/backtrace.cc
@@ -368,7 +368,10 @@ backtrace_foreach(backtrace_cb cb, coro_context *coro_ctx, void *cb_ctx)
 {
 	unw_cursor_t unw_cur;
 	unw_context_t unw_ctx;
-	coro_unwcontext(&unw_ctx, coro_ctx);
+	if (coro_ctx != NULL)
+		coro_unwcontext(&unw_ctx, coro_ctx);
+	else
+		unw_getcontext(&unw_ctx);
 	unw_init_local(&unw_cur, &unw_ctx);
 	int frame_no = 0;
 	unw_word_t sp = 0, old_sp = 0, ip, offset;
-- 
2.19.0

[tarantool-patches] Re: [PATCH 2/3] Proper unwind for currently executing fiber

[Konstantin Osipov]

* Georgy Kirichenko <georgy@tarantool.org> [18/09/22 00:21]:
> A fiber's coro context stores execution state for a corresponding
> already yielded fiber. If fiber is on the execution then it hasn't
> valid stored coro state and might be backtraced without a special unwind
> context builder.

I did not understand what's going on from the comment. I assume
this is an optimization, in which you try to avoid re-fetching the
registers in some cases?

Please clarify.
> --
-- 
Konstantin Osipov, Moscow, Russia, +7 903 626 22 32
http://tarantool.io - www.twitter.com/kostja_osipov

[tarantool-patches] Re: [PATCH 2/3] Proper unwind for currently executing fiber

[Georgy Kirichenko]

[-- Attachment #1: Type: text/plain, Size: 1285 bytes --]

On Wednesday, September 26, 2018 2:34:02 AM MSK Konstantin Osipov wrote:
> * Georgy Kirichenko <georgy@tarantool.org> [18/09/22 00:21]:
> > A fiber's coro context stores execution state for a corresponding
> > already yielded fiber. If fiber is on the execution then it hasn't
> > valid stored coro state and might be backtraced without a special unwind
> > context builder.
> 
> I did not understand what's going on from the comment. I assume
> this is an optimization, in which you try to avoid re-fetching the
> registers in some cases?
> 
> Please clarify.
> 
> > --

Each yielded fiber has a preserved coro state stored in a corresponding 
variable however an executing fiber has a volatile state placed in CPU 
registers (stack pointer, instruction pointer and non-volatile registers) and 
corresponding context-storing variable value is invalid.
For already yielded fiber we use a special asm-written handler to make a 
temporary switch to the preserved state and capture executing context what is 
not needed for executing fiber. 
After the patch for the executing fiber NULL is passed to the backtrace 
function as coro context and then backtrace function could decide should it 
use special context-switching handler or might just use unw_getcontext from 
the unwind library.

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

[tarantool-patches] Re: [PATCH 2/3] Proper unwind for currently executing fiber

[Konstantin Osipov]

* Georgy Kirichenko <georgy@tarantool.org> [18/09/26 10:46]:
> On Wednesday, September 26, 2018 2:34:02 AM MSK Konstantin Osipov wrote:
> > * Georgy Kirichenko <georgy@tarantool.org> [18/09/22 00:21]:
> > > A fiber's coro context stores execution state for a corresponding
> > > already yielded fiber. If fiber is on the execution then it hasn't
> > > valid stored coro state and might be backtraced without a special unwind
> > > context builder.
> > 
> > I did not understand what's going on from the comment. I assume
> > this is an optimization, in which you try to avoid re-fetching the
> > registers in some cases?
> > 
> > Please clarify.
> > 
> > > --
> 
> Each yielded fiber has a preserved coro state stored in a corresponding 
> variable however an executing fiber has a volatile state placed in CPU 
> registers (stack pointer, instruction pointer and non-volatile registers) and 
> corresponding context-storing variable value is invalid.
> For already yielded fiber we use a special asm-written handler to make a 
> temporary switch to the preserved state and capture executing context what is 
> not needed for executing fiber. 
> After the patch for the executing fiber NULL is passed to the backtrace 
> function as coro context and then backtrace function could decide should it 
> use special context-switching handler or might just use unw_getcontext from 
> the unwind library.

this is more clear, please add to the source code as a comment.
ok to push.


-- 
Konstantin Osipov, Moscow, Russia, +7 903 626 22 32
http://tarantool.io - www.twitter.com/kostja_osipov

[tarantool-patches] [PATCH 2/3] Proper unwind for currently executing fiber

[Georgy Kirichenko]

Each yielded fiber has a preserved coro state stored in a corresponding
variable however an executing fiber has a volatile state placed in CPU
registers (stack pointer, instruction pointer and non-volatile registers)
and corresponding context-storing variable value is invalid.
For already yielded fiber we have to use a special asm-written handler to make
a temporary switch to the preserved state and capture executing context what
is not needed for executing fiber.
After the patch for the executing fiber NULL is passed to the backtrace
function as coro context and then backtrace function could decide should
it use special context-switching handler or might just use unw_getcontext
from the unwind library.
---
 src/backtrace.cc | 22 +++++++++++++++++++++-
 1 file changed, 21 insertions(+), 1 deletion(-)

diff --git a/src/backtrace.cc b/src/backtrace.cc
index 2512bc045..d59fd5879 100644
--- a/src/backtrace.cc
+++ b/src/backtrace.cc
@@ -363,12 +363,32 @@ __asm__ volatile(
 #endif
 }
 
+/*
+ * Call `cb' callback for each `coro_ctx' contained frame or the current
+ * executed coroutine if `coro_ctx' is NULL. A coro_context is a structure
+ * created on each coroutine yield to store execution context so for an on-CPU
+ * coroutine there is no valid coro_context could be defined and NULL is
+ * passed.
+*/
 void
 backtrace_foreach(backtrace_cb cb, coro_context *coro_ctx, void *cb_ctx)
 {
 	unw_cursor_t unw_cur;
 	unw_context_t unw_ctx;
-	coro_unwcontext(&unw_ctx, coro_ctx);
+	if (coro_ctx == NULL) {
+		/*
+		 * Current executing coroutine and simple unw_getcontext
+		 * should function.
+		 */
+		unw_getcontext(&unw_ctx);
+	} else {
+		/*
+		 * Execution context is stored in the coro_ctx
+		 * so use special context-switching handler to
+		 * capture an unwind context.
+		 */
+		coro_unwcontext(&unw_ctx, coro_ctx);
+	}
 	unw_init_local(&unw_cur, &unw_ctx);
 	int frame_no = 0;
 	unw_word_t sp = 0, old_sp = 0, ip, offset;
-- 
2.19.0

Re: [tarantool-patches] [PATCH 2/3] Proper unwind for currently executing fiber

[Vladimir Davydov]

The patch looks good, but unfortunately it leads to box/access.test.lua
crash when tarantool is built in release mode. I've no idea why this
could happen. Please investigate.

https://travis-ci.org/tarantool/tarantool/jobs/436995648

box/admin.test.lua

[Instance "box" killed by signal: 6 (SIGABRT)]
Segmentation fault
  code: SEGV_MAPERR
  addr: 0xffffffffffff8750
  context: 0x7fffe94ef7c0
  siginfo: 0x7fffe94ef8f0
  rax      0x4fd4a0           5231776
  rbx      0x7fffe94ff610     140737107719696
  rcx      0x7fffe9400d70     140737106677104
  rdx      0x40153748         1075132232
  rsi      0x7fffe94ff610     140737107719696
  rdi      0xffffffffffff8708 -30968
  rsp      0x7fffe94efd70     140737107656048
  rbp      0x7fffe94efd88     140737107656072
  r8       0x400003b8         1073742776
  r9       0x98               152
  r10      0x7fffe94ef7e0     140737107654624
  r11      0x7ffff4238a3b     140737289357883
  r12      0x1d               29
  r13      0xf                15
  r14      0x40001000         1073745920
  r15      0x4ea7d0           5154768
  rip      0x7ffff4238a3b     140737289357883
  eflags   0x10212            66066
  cs       0x33               51
  gs       0x0                0
  fs       0x0                0
  cr2      0xffffffffffff8750 -30896
  err      0x7                7
  oldmask  0x0                0
  trapno   0xe                14
Current time: 1538752048
Please file a bug at http://github.com/tarantool/tarantool/issues
Attempting backtrace... Note: since the server has already crashed,
this may fail as well
#0  0x4fe559 in print_backtrace+9
#1  0x412d0d in _ZL12sig_fatal_cbiP9siginfo_tPv+bd
#2  0x7ffff48936d0 in _L_unlock_13+34
#3  0x7ffff4238a3b in _Ux86_64_getcontext+0
#4  0x4fd4b1 in _ZL16unw_getcontext_fP8ucontextPv+11
#5  0x4fe3b6 in backtrace_foreach+66
#6  0x5077f0 in coio_wait+80
#7  0x4ea86f in lbox_socket_iowait+9f
#8  0x518767 in lj_BC_FUNCC+34
#9  0x529662 in lua_pcall+32
#10 0x4e9fa3 in luaT_call+13
#11 0x4e4976 in lua_fiber_run_f+56
#12 0x41270c in _ZL16fiber_cxx_invokePFiP13__va_list_tagES0_+c
#13 0x4fb210 in fiber_loop+30
#14 0x63ae7f in coro_init+3f