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

[Vladimir Davydov <vdavydov.dev@gmail.com>]

On Thu, Oct 04, 2018 at 10:55:22AM +0300, Georgy Kirichenko wrote:
> Trace corresponding Lua state as well as normal C stack frames while
> fiber backtracing. This might be useful for debugging purposes.
> 
> Fixes: #3538

It would be nice to give an example of what a trace back looks like now:

- - '#1  0x560068107478 in fiber_yield_timeout+154'
  - '#2  0x5600681108c4 in fiber_channel_get_msg_timeout+553'
  - '#3  0x5600680ec711 in luaT_fiber_channel_get+228'
  - LUA#1  get in =[C] at line -1
  - LUA#2  f1 in @../test.lua at line 10
  - LUA#3  f2 in @../test.lua at line 14
  - LUA#4  (unnamed) in @../test.lua at line 18
  - '#5  0x560068151863 in lua_pcall+398'
  - '#6  0x5600680f2279 in luaT_call+41'
  - '#7  0x5600680eb2a1 in lua_fiber_run_f+116'
  - '#8  0x560067ffde24 in fiber_cxx_invoke(int (*)(__va_list_tag*), __va_list_tag*)+30'
  - '#9  0x560068107a81 in fiber_loop+130'
  - '#10 0x5600682db35b in coro_init+76'
  - '#11 (nil) in +76'

To be honest I find it ugly, but at the same time I fail to suggest
anything less ugly. May be, we could use through numbering for Lua
and C frames?

- - '#1  0x560068107478 in fiber_yield_timeout+154'
  - '#2  0x5600681108c4 in fiber_channel_get_msg_timeout+553'
  - '#3  0x5600680ec711 in luaT_fiber_channel_get+228'
  - '#4  <Lua> get in =[C] at line -1'
  - '#5  <Lua> f1 in @../test.lua at line 10'
  - '#6  <Lua> f2 in @../test.lua at line 14'
  - '#7  <Lua> (unnamed) in @../test.lua at line 18'
  - '#8  0x560068151863 in lua_pcall+398'
  - '#9  0x5600680f2279 in luaT_call+41'
  - '#10 0x5600680eb2a1 in lua_fiber_run_f+116'
  - '#11 0x560067ffde24 in fiber_cxx_invoke(int (*)(__va_list_tag*), __va_list_tag*)+30'
  - '#12 0x560068107a81 in fiber_loop+130'
  - '#13 0x5600682db35b in coro_init+76'

Or alternatively, we could turn a frame corresponding to lj_BC_FUNCC
into an array, which would contain Lua stack frames:

- - '#1  0x560068107478 in fiber_yield_timeout+154'
  - '#2  0x5600681108c4 in fiber_channel_get_msg_timeout+553'
  - '#3  0x5600680ec711 in luaT_fiber_channel_get+228'
  - - '#4  0x5601b399da2b in lj_BC_FUNCC+52'
  - - <Lua> get in =[C] at line -1
  - - <Lua> f1 in @../test.lua at line 10
  - - <Lua> f2 in @../test.lua at line 14
  - - <Lua> (unnamed) in @../test.lua at line 18
  - '#5  0x560068151863 in lua_pcall+398'
  - '#6  0x5600680f2279 in luaT_call+41'
  - '#7  0x5600680eb2a1 in lua_fiber_run_f+116'
  - '#8  0x560067ffde24 in fiber_cxx_invoke(int (*)(__va_list_tag*), __va_list_tag*)+30'
  - '#9  0x560068107a81 in fiber_loop+130'
  - '#10 0x5600682db35b in coro_init+76'
  - '#11 (nil) in +76'

> ---
>  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)

Nitpicking: this line and a few below are longer than 80 characters.
I don't see any reason why you couldn't split them.

> +{
> +	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++;
> +		}

I think you could rewrite this code with just one loop. It would make it
more succinct. Would it make it more readable though?

> +	} else {

I think we should include lj_BC_FUNCC into the output too.

> +		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