Re: [Tarantool-patches] [PATCH luajit 6/7] sysprof: introduce Lua API

[Sergey Kaplun via Tarantool-patches <tarantool-patches@dev.tarantool.org>]

Hi, Maxim!

Thanks for the patch!

Please consider my comments below.

On 08.09.21, Maxim Kokryashkin wrote:
> This commit introduces Lua API for sysprof, so it is now possible to
> call it from anywhere in a Lua script. All of the parameters are passed
> inside a single Lua table.
> The following options are supported:
> - mode:     "D" (Default mode, only virtual machine state counters)
>             "L" (Leaf mode, shows the last frame on the stack)
>             "C" (Callchain mode, full stack dump)
> - interval: time between samples

Please add note that this is time in miliseconds.

> - path:     Path to file in which profiling data should be stored

Minor: It would be nice to mention the return values.

> 
> Part of tarantool/tarantool#781
> ---
>  src/lib_misc.c                                | 224 ++++++++++++++++++
>  .../misclib-sysprof-lapi.test.lua             | 105 ++++++++
>  2 files changed, 329 insertions(+)
>  create mode 100644 test/tarantool-tests/misclib-sysprof-lapi.test.lua
> 
> diff --git a/src/lib_misc.c b/src/lib_misc.c
> index a44476e0..a3423cdd 100644
> --- a/src/lib_misc.c
> +++ b/src/lib_misc.c

I have the following warnings when compile with
| -DCMAKE_C_FLAGS="-Wextra -Wdeclaration-after-statement -Wredundant-decls -Wshadow -Wpointer-arith"

| /home/burii/reviews/luajit/sysprof/src/lib_misc.c: In function 'set_output_path':
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c:201:3: warning: ISO C90 forbids mixed declarations and code [-Wdeclaration-after-statement]
|   201 |   struct profile_ctx *ctx = opt->ctx;
|       |   ^~~~~~
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c: In function 'parse_output_path':
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c: In function 'set_output_path':
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c:201:3: warning: ISO C90 forbids mixed declarations and code [-Wdeclaration-after-statement]
|   201 |   struct profile_ctx *ctx = opt->ctx;
|       |   ^~~~~~
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c: In function 'parse_output_path':
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c:210:74: warning: unused parameter 'opt' [-Wunused-parameter]
|   210 | const char* parse_output_path(lua_State *L, struct luam_sysprof_options *opt, int idx) {
|       |                                             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^~~
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c: In function 'parse_options':
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c:226:7: warning: ISO C90 forbids mixed declarations and code [-Wdeclaration-after-statement]
|   226 |       const char* path = parse_output_path(L, opt, 1);
|       |       ^~~~~
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c: In function 'lj_cf_misc_sysprof_start':
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c:296:3: warning: ISO C90 forbids mixed declarations and code [-Wdeclaration-after-statement]
|   296 |   const struct luam_sysprof_config conf = {buffer_writer_default, on_stop_cb_default, NULL};
|       |   ^~~~~
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c:210:74: warning: unused parameter 'opt' [-Wunused-parameter]
|   210 | const char* parse_output_path(lua_State *L, struct luam_sysprof_options *opt, int idx) {
|       |                                             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^~~
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c: In function 'parse_options':
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c:226:7: warning: ISO C90 forbids mixed declarations and code [-Wdeclaration-after-statement]
|   226 |       const char* path = parse_output_path(L, opt, 1);
|       |       ^~~~~
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c: In function 'lj_cf_misc_sysprof_start':
| /home/burii/reviews/luajit/sysprof/src/lib_misc.c:296:3: warning: ISO C90 forbids mixed declarations and code [-Wdeclaration-after-statement]
|   296 |   const struct luam_sysprof_config conf = {buffer_writer_default, on_stop_cb_default, NULL};
|       |   ^~~~~

> @@ -145,6 +145,218 @@ static int on_stop_cb_default(void *opt, uint8_t *buf)
>    return fclose(stream);
>  }
>  
> +/* ----- misc.sysprof module ---------------------------------------------- */
> +
> +/* Not loaded by default, use: local profile = require("misc.sysprof") */

Looks like it is not true. See example here [1].
Also, I see no reason for differnce between sysprof and memprof here.

> +#define LJLIB_MODULE_misc_sysprof
> +
> +/* The default profiling interval equals to 11 ms. */
> +#define SYSPROF_DEFAULT_INTERVAL (11)

Why 11 and not 10, 9 or something else?
Nit: () are excess

> +#define SYSPROF_DEFAULT_OUTPUT "sysprof.bin"

I suppose that it is better if user makes a mistake in any parameter you
should raise an error to inform him.

> +
> +int parse_sysprof_opts(lua_State *L, struct luam_sysprof_options *opt, int idx) {
> +  GCtab *options = lj_lib_checktab(L, idx);

Looks like the index is used only here, so we can check this outside
this function. Also, I'm a little bit frightened by the difference with
memprof. User may set this parameter in the 1st argument and in the
opttable, what we should prefer to use?

I suggest to similarize API with memprof's -- so the first argument is
always a string contains the filename for profiler's output. The second
is a table with others options (as we agreed offline, but I still think
that it is not Lua-style API) or nil. If the second argument is nil we
still can run profiler with default options (i.e. interval and mode "D"
as the most harmless). If the option has the wrong type (a function or
a table, etc. instead a string) we should raise an error.

If the second argument is the table with only "mode" or only "interval"
key is set we use the default value for another. If there is any unknown
option (for example "inteval") we must raise an error (unknown option),
to notify the user that he tries to use a wrong option in the table.

OTOH, I don't know how the API should look when we profiling in
Default mode, i.e. without any output to file. So maybe it is better
always expect the table as the first argument. When the profiling mode
is Default we should raise and error that, path argument is invalid.

Thoughts?

> +
> +  /* get profiling mode */

Typo: s/get/Get/ s/mode/mode./

> +  {
> +    cTValue *mode_opt = lj_tab_getstr(options, lj_str_newlit(L, "mode"));
> +    char mode = 0;
> +    if (mode_opt) {

Nit: {} are excess.

> +      mode = *strVdata(mode_opt);

There is no guarantee that the value is a string, so the behaviour is
undefined.

> +    }

Default mode is not taking into account here, see the comment above.

> +
> +    switch (mode) {
> +      case 'D':
> +        opt->mode = LUAM_SYSPROF_DEFAULT;

Nit: We use quater-half tabs code style in LuaJIT.
So 8spaces should be replased with a single tab.
Here and below.

> +        break;
> +      case 'L':
> +        opt->mode = LUAM_SYSPROF_LEAF;
> +        break;
> +      case 'C':
> +        opt->mode = LUAM_SYSPROF_CALLGRAPH;
> +        break;
> +      default:
> +        return SYSPROF_ERRUSE;

What is the behaviour in case when mode is "CDL", and when is "DCL"?

> +    }
> +  }
> +
> +  /* Get profiling interval. */
> +  {
> +    cTValue *interval = lj_tab_getstr(options, lj_str_newlit(L, "interval"));
> +    opt->interval = SYSPROF_DEFAULT_INTERVAL;
> +    if (interval) {
> +      int32_t signed_interval = numberVint(interval);

There is no guarantee that interval TValue is a number or string, we
should check it.

| $ src/luajit -e 'misc.sysprof.start( {mode = "C", interval = function() end, path = "/tmp/sysprof.bin"})'
| luajit: /home/burii/reviews/luajit/sysprof/src/lj_obj.h:1025: numberVint: Assertion `(((o)->it) < 0xfffeffffu)' failed.
| Aborted

> +      if (signed_interval < 1) {

Nit: {} are excess.

> +        return SYSPROF_ERRUSE;
> +      }
> +      opt->interval = signed_interval;
> +    }
> +  }
> +
> +  return SYSPROF_SUCCESS;

According to RFC [2] we can use set path via this table, however the
corresponding check is omited.

| local started, err, errno = misc.sysprof.start{
|   mode = profiling_mode,
|   interval = sampling_interval,
|   path = fname,
| }

But, as I said, for more consistency with memprof we can drop path from
options table.

> +}
> +
> +int set_output_path(const char* path, struct luam_sysprof_options *opt) {

Typo: s/char* path/char *path/

> +  lua_assert(path != NULL);
> +  struct profile_ctx *ctx = opt->ctx;
> +  FILE *stream = fopen(path, "wb");
> +  if(!stream) {
> +    return SYSPROF_ERRIO;
> +  }
> +  ctx->stream = stream;
> +  return SYSPROF_SUCCESS;
> +}

I don't understand this fucntion's destiny. Why we can't just use fopen
and check than returned value isn't NULL?

> +
> +const char* parse_output_path(lua_State *L, struct luam_sysprof_options *opt, int idx) {
> +  /* By default, sysprof writes events to a `sysprof.bin` file. */

See comment about default file above.

> +  const char *path = luaL_checkstring(L, idx);
> +  return path ? path : SYSPROF_DEFAULT_OUTPUT;
> +}
> +
> +int parse_options(lua_State *L, struct luam_sysprof_options *opt)
> +{
> +  int status = SYSPROF_SUCCESS;
> +
> +  switch(lua_gettop(L)) {

See comment about Lua API above.

> +    case 2:
> +      if(!(lua_isstring(L, 1) && lua_istable(L, 2))) {
> +        status = SYSPROF_ERRUSE;
> +        break;
> +      }
> +      const char* path = parse_output_path(L, opt, 1); 
                                                         ^
Minor: Trailing whitespace here.-------------------------^

> +      status = set_output_path(path, opt);
> +      if(status != SYSPROF_SUCCESS) 
                                      ^
Minor: Trailing whitespace here.------^

> +        break;
> +
> +      status = parse_sysprof_opts(L, opt, 2);
> +      break;
> +    case 1:
> +      if(!lua_istable(L, 1)) {
> +        status = SYSPROF_ERRUSE;
> +        break;
> +      }
> +      status = parse_sysprof_opts(L, opt, 1);
> +      if(status != SYSPROF_SUCCESS)
> +        break;
> +      status = set_output_path(SYSPROF_DEFAULT_OUTPUT, opt);
> +      break;
> +    default:
> +      status = SYSPROF_ERRUSE;
> +      break;
> +  } 
      ^
Minor: Trailing whitespace here.

> +  return status;
> +}
> +
> +int sysprof_error(lua_State *L, int status)
> +{
> +  switch (status) {
> +    case SYSPROF_ERRUSE:
> +      lua_pushnil(L);
> +      lua_pushstring(L, err2msg(LJ_ERR_PROF_MISUSE));
> +      lua_pushinteger(L, EINVAL);
> +      return 3;
> +    case SYSPROF_ERRRUN:

LJ_ERR_PROF_ISRUNNING and LJ_ERR_PROF_NOTRUNNING is defined only, when
LJ_HASMEMPROF || LJ_HASSYSPROF, so it must be the corresponding ifdef
here.

> +      lua_pushnil(L);
> +      lua_pushstring(L, err2msg(LJ_ERR_PROF_ISRUNNING));
> +      lua_pushinteger(L, EINVAL);
> +      return 3;
> +    case SYSPROF_ERRSTOP:
> +      lua_pushnil(L);
> +      lua_pushstring(L, err2msg(LJ_ERR_PROF_NOTRUNNING));
> +      lua_pushinteger(L, EINVAL);
> +      return 3;
> +    case SYSPROF_ERRIO:
> +      return luaL_fileresult(L, 0, NULL);
> +    default:
> +      lua_assert(0);
> +      return 0;
> +  }
> +}
> +
> +/* local res, err, errno = sysprof.start(options) */
> +LJLIB_CF(misc_sysprof_start)
> +{
> +  int status = SYSPROF_SUCCESS;
> +
> +  struct luam_sysprof_options opt = {};
> +  struct profile_ctx *ctx = NULL;
> +
> +  ctx = lj_mem_new(L, sizeof(*ctx));

We don't need this context for streaming events if profiled mode is
default. Also we don't need to open any files to write data.

| src/luajit -e 'misc.sysprof.start( {mode = "D", interval = 1, path = "/tmp/sysprof.bin"})'
| luajit: /home/burii/reviews/luajit/sysprof/src/lj_state.c:199: close_state: Assertion `g->gc.total == sizeof(GG_State)' failed.
| Aborted

> +  ctx->g = G(L);
> +  opt.ctx = ctx;
> +  opt.buf = ctx->buf;
> +  opt.len = STREAM_BUFFER_SIZE;
> +
> +  status = parse_options(L, &opt);
> +  if (LJ_UNLIKELY(status != PROFILE_SUCCESS)) {
> +    lj_mem_free(ctx->g, ctx, sizeof(*ctx));
> +    return sysprof_error(L, status);
> +  }
> +
> +  const struct luam_sysprof_config conf = {buffer_writer_default, on_stop_cb_default, NULL};

Nit: linewidth is more than 80 symbols. Also, I see nothing bad to
set config fields per entry.

Also, we can't use non async-signal-safe functions in writer like
fwrite.

> +  status = luaM_sysprof_configure(&conf);
> +  if (LJ_UNLIKELY(status != PROFILE_SUCCESS)) {

We need to call `on_stop` callback manually here.

| $ src/luajit -e 'misc.sysprof.start( {mode = "C", interval = 1 end, path = "/tmp/sysprof.bin"}) misc.sysprof.start( {mode = "C", interval = 1 end, path = "/tmp/sysprof.bin"})'
| luajit: /home/burii/reviews/luajit/sysprof/src/lj_state.c:199: close_state: Assertion `g->gc.total == sizeof(GG_State)' failed.
| Aborted

> +    return sysprof_error(L, status);

Nit: {} are excess.

> +  }
> +
> +  status = luaM_sysprof_start(L, &opt);
> +  if (LJ_UNLIKELY(status != PROFILE_SUCCESS)) {
> +    /* Allocated memory will be freed in on_stop callback. */
> +    return sysprof_error(L, status);

Nit: {} are excess.

> +  }
> +
> +  lua_pushboolean(L, 1);
> +  return 1;
> +}
> +
> +/* local res, err, errno = profile.sysprof_stop() */
> +LJLIB_CF(misc_sysprof_stop)
> +{
> +  int status = luaM_sysprof_stop(L);
> +  if (LJ_UNLIKELY(status != PROFILE_SUCCESS)) {

Nit: {} are excess.

> +    return sysprof_error(L, status);
> +  }
> +  lua_pushboolean(L, 1);
> +  return 1;
> +}
> +
> +/* local counters, err, errno = sysprof.report() */
> +LJLIB_CF(misc_sysprof_report)
> +{
> +  struct luam_sysprof_counters counters = {};
> +  GCtab *data_tab = NULL;
> +  GCtab *count_tab = NULL;
> +
> +  int status = luaM_sysprof_report(&counters);
> +  if (status != SYSPROF_SUCCESS) {

Nit: {} are excess.

> +    return sysprof_error(L, status);
> +  }
> +
> +  lua_createtable(L, 0, 3);
> +  data_tab = tabV(L->top - 1);
> +
> +  setnumfield(L, data_tab, "samples", counters.samples);
> +  setnumfield(L, data_tab, "overruns", counters.overruns);
> +
> +  lua_createtable(L, 0, LJ_VMST__MAX + 1);

May be it is better to use 1 level tab here. Wait for the second
reviewer opinion.

> +  count_tab = tabV(L->top - 1);
> +
> +  setnumfield(L, count_tab, "INTERP", counters.vmst_interp);
> +  setnumfield(L, count_tab, "LFUNC",  counters.vmst_lfunc);
> +  setnumfield(L, count_tab, "FFUNC",  counters.vmst_ffunc);
> +  setnumfield(L, count_tab, "CFUNC",  counters.vmst_cfunc);
> +  setnumfield(L, count_tab, "GC",     counters.vmst_gc);
> +  setnumfield(L, count_tab, "EXIT",   counters.vmst_exit);
> +  setnumfield(L, count_tab, "RECORD", counters.vmst_record);
> +  setnumfield(L, count_tab, "OPT",    counters.vmst_opt);
> +  setnumfield(L, count_tab, "ASM",    counters.vmst_asm);
> +  setnumfield(L, count_tab, "TRACE",  counters.vmst_trace);
> +
> +  lua_setfield(L, -2, "vmstate");
> +
> +  return 1;
> +}
> +
>  /* ----- misc.memprof module ---------------------------------------------- */
>  
>  #define LJLIB_MODULE_misc_memprof

Nit: Empty line after LJLIB_MODULE_misc_memprof is missed.

> @@ -237,7 +449,19 @@ LJLIB_CF(misc_memprof_stop)
>  
>  LUALIB_API int luaopen_misc(struct lua_State *L)
>  {
> +  int status = SYSPROF_SUCCESS;
> +  struct luam_sysprof_config config = {};
> +
> +  config.writer = buffer_writer_default;
> +  config.on_stop = on_stop_cb_default;
> +  status = luaM_sysprof_configure(&config);
> +  if (LJ_UNLIKELY(status != PROFILE_SUCCESS)) {
> +    return sysprof_error(L, status);
> +  }

Don't get this: Why do we need to configure sysprof when loading module,
if we configure it manually during start() call?

> +
>    LJ_LIB_REG(L, LUAM_MISCLIBNAME, misc);
>    LJ_LIB_REG(L, LUAM_MISCLIBNAME ".memprof", misc_memprof);
> +  LJ_LIB_REG(L, LUAM_MISCLIBNAME ".sysprof", misc_sysprof);
> +
>    return 1;
>  }
> diff --git a/test/tarantool-tests/misclib-sysprof-lapi.test.lua b/test/tarantool-tests/misclib-sysprof-lapi.test.lua
> new file mode 100644
> index 00000000..17d83d1b
> --- /dev/null
> +++ b/test/tarantool-tests/misclib-sysprof-lapi.test.lua
> @@ -0,0 +1,105 @@

We need to use the same skipcondition as for memprof here.

> +local tap = require("tap")
> +
> +local test = tap.test("misc-sysprof-lapi")
> +test:plan(14)
> +
> +jit.off()
> +jit.flush()
> +
> +local bufread = require "utils.bufread"
> +local symtab = require "utils.symtab"

Nit: please be consistent: use `require("modulename")`.

> +
> +local TMP_BINFILE = arg[0]:gsub(".+/([^/]+)%.test%.lua$", "%.%1.sysprofdata.tmp.bin")
> +local BAD_PATH = arg[0]:gsub(".+/([^/]+)%.test%.lua$", "%1/sysprofdata.tmp.bin")
> +
> +local function payload()
> +  local function fib(n)
> +    if n <= 1 then
> +      return n
> +    end
> +    return fib(n - 1) + fib(n - 2)
> +  end
> +  return fib(32)
> +end
> +
> +local function generate_output(file, opts)
> +  file = file or "sysprof.bin"

Please, remove default file name.

> +  local res, err = misc.sysprof.start(file, opts)
> +  assert(res, err)
> +
> +  payload()
> +
> +  res,err = misc.sysprof.stop()
> +  assert(res, err)
> +end

Nit: missed empty line.
Here and below.

> +--## GENERAL ###############################################################--

Nit: this mixing style looks confusing. Please use only `--`.
Here and below.

> +
> +--wrong profiling mode

Typo: s/--wrong/-- Wrong/
Typo: s/mode/mode./

> +local res, err, errno = misc.sysprof.start{ mode = "A" }
> +test:ok(res == nil and err:match("profiler misuse"))
> +test:ok(type(errno) == "number")
> +
> +--already running

Typo: s/--already running/-- Already running./

> +res, err = misc.sysprof.start{ mode = "D" }
> +assert(res, err)
> +
> +res, err, errno = misc.sysprof.start{ mode = "D" }
> +print(err)

Please remove this debugging output.

> +test:ok(res == nil and err:match("profiler misuse"))
> +test:ok(type(errno) == "number")
> +
> +res, err = misc.sysprof.stop()
> +assert(res, err)
> +
> +--not running

Typo: s/--not running/-- Not running./

> +res, err, errno = misc.sysprof.stop()
> +test:ok(res == nil and err:match("profiler is not running"))
> +test:ok(type(errno) == "number")
> +
> +--bad path

Typo: s/--bad path/-- Bad path./

> +res, err, errno = misc.sysprof.start(BAD_PATH, { mode = "C" })
> +test:ok(res == nil and err:match("No such file or directory"))
> +test:ok(type(errno) == "number")
> +
> +--bad interval

Typo: s/--bad interval/-- Bad interval./

> +res, err, errno = misc.sysprof.start{ mode = "C", interval = -1 }
> +test:ok(res == nil and err:match("profiler misuse"))
> +test:ok(type(errno) == "number")
> +--## DEFAULT MODE ##########################################################--
> +
> +res, err = pcall(generate_output, nil, { mode = "D", interval = 11 })
> +if res == nil then

`pcall()` returns either true when there is no error raised, either
false in case of an error.
I suppose we should remove TMP file in case of error here.

> +  error(err)
> +end
> +
> +local report = misc.sysprof.report()
> +
> +test:ok(report.samples > 0)  -- TODO: more accurate test?

The test looks OK to me. Maybe we can use a specific function to sleep
every N ms, where N is the interval value, so then the amount of sleep
calls should be equal to the amount of samples.

> +test:ok(report.vmstate.LFUNC > 0)
> +test:ok(report.vmstate.TRACE == 0)
> +
> +-- with very big interval

Typo: s/with/With/
Typo: s/interval/interval./

> +res, err = pcall(generate_output, nil, { mode = "D", interval = 1000 })
> +if res == nil then

`pcall()` returns either true when there is no error raised, either
false in case of an error.
I suppose we should remove TMP file in case of error here.

> +  error(err)
> +end
> +
> +report = misc.sysprof.report()
> +test:ok(report.samples == 0)
> +
> +--## CALL MODE #############################################################--
> +
> +res, err = pcall(
> +  generate_output, TMP_BINFILE, { mode = "C", interval = 11 }
> +)
> +if res == nil then

`pcall()` returns either true when there is no error raised, either
false in case of an error.
I suppose we should remove TMP file in case of error here.

> +  error(err)
> +end
> +
> +local reader = bufread.new(TMP_BINFILE)
> +symtab.parse(reader)
> +
> +os.remove(TMP_BINFILE)
> +
> +jit.on()
> +os.exit(test:check() and 0 or 1)

What about Leaf mode? I suppose, that we can check it works like for
Callgraph mode.

> -- 
> 2.33.0
> 

-- 
Best regards,
Sergey Kaplun