[Tarantool-patches] [PATCH luajit 2/2] test: rewrite sysprof test using managed execution

[Igor Munkin via Tarantool-patches <tarantool-patches@dev.tarantool.org>]

Often tests for sampling profiler require long running loops to be
executed, so a certain situation is likely to occur. Thus the test added
in the commit 285a1b0a16c1c3224ab93f7cf1fef17ab29e4ab4 ("sysprof: fix
crash during FFUNC stream") expects FFUNC VM state (and even the
particular instruction to be executed) at the moment when stacktrace is
being collected. Unfortunately, it leads to test routine hang for
several environments and if it does not we cannot guarantee that the
desired scenario is tested (only rely on statistics). As a result the
test for the aforementioned patch was disabled for Tarantool CI in the
commit fef60a1052b8444be61e9a9932ab4875aff0b2ed ("test: prevent hanging
Tarantool CI by sysprof test") until the issue is not resolved.

This patch introduces the new approach for testing our sampling profiler
via <ptrace> implementing precise managed execution of the profiled
instance mentioned in tarantool/tarantool#9387.

Instead of running around <tostring> gazillion times we accurately step
to the exact place where the issue reproduces and manually emit SIGPROF
to the Lua VM being profiled. The particular approach implemented in
this patch is described below.

As it was mentioned, the test makes sysprof to collect the particular
event (FFUNC) at the certain instruction in Lua VM (<lj_fff_res1>) to
reproduce the issue from tarantool/tarantool#8594. Hence it's enough to
call <tostring> fast function in the profiled instance (i.e. "tracee").
To emit SIGPROF right at <lj_fff_res1> in scope of <tostring> builtin,
the manager (i.e. "tracer") is implemented.

Here are the main steps (see comments and `man 2 ptrace' for more info):
  1. Poison <int 3> instruction as the first instruction at
     <lj_ff_tostring> to stop at the beginning of the fast function;
  2. Resume the "tracee" from the "tracer";
  3. Hit the emitted interruption, restore the original instruction and
     "rewind" the RIP to "replay" the instruction at <lj_ff_tostring>;
  4. Do the hack 1-3 for <lj_fff_res1>;
  5. Emit SIGPROF while resumimg the "tracee";

As a result sysprof collects the full backtrace with <tostring> fast
function as the topmost frame.

Resolves tarantool/tarantool#9387
Follows up tarantool/tarantool#8594

Signed-off-by: Igor Munkin <imun@tarantool.org>
---
 .../gh-8594-sysprof-ffunc-crash.test.c        | 269 ++++++++++++++++++
 .../gh-8594-sysprof-ffunc-crash.test.lua      |  55 ----
 2 files changed, 269 insertions(+), 55 deletions(-)
 create mode 100644 test/tarantool-c-tests/gh-8594-sysprof-ffunc-crash.test.c
 delete mode 100644 test/tarantool-tests/gh-8594-sysprof-ffunc-crash.test.lua

diff --git a/test/tarantool-c-tests/gh-8594-sysprof-ffunc-crash.test.c b/test/tarantool-c-tests/gh-8594-sysprof-ffunc-crash.test.c
new file mode 100644
index 00000000..4caed8cb
--- /dev/null
+++ b/test/tarantool-c-tests/gh-8594-sysprof-ffunc-crash.test.c
@@ -0,0 +1,269 @@
+#include "lauxlib.h"
+#include "lmisclib.h"
+#include "lua.h"
+
+#include "test.h"
+#include "utils.h"
+
+#include <signal.h>
+#include <sys/ptrace.h>
+#include <sys/user.h>
+#include <sys/wait.h>
+#include <unistd.h>
+
+/* XXX: Still need normal assert inside <tracee> and helpers. */
+#undef NDEBUG
+#include <assert.h>
+
+/*
+ * XXX: The test is *very* Linux/x86_64 specific. Fortunately, so
+ * does the sampling profiler. <lj_arch.> is needed for LUAJIT_OS
+ * and LUAJIT_TARGET.
+ */
+#include "lj_arch.h"
+
+#if LUAJIT_OS == LUAJIT_OS_LINUX && LUAJIT_TARGET == LUAJIT_ARCH_X64
+
+/*
+ * XXX: The test makes sysprof to collect the particular event
+ * (FFUNC) at the particular instruction (<lj_fff_res1>) to
+ * reproduce the issue #8594. Hence it's enough to call <tostring>
+ * fast function (this is done in <tracee> function). To emit
+ * SIGPROF right at <lj_fff_res1> in scope of <tostring> fast
+ * function, the managed execution is implemented in the function
+ * <tracer>: <int 3> instruction is poisoned as the first
+ * instruction at <lj_ff_tostring> to stop <tracee> at the
+ * beginning of the fast function; <tracer> resumes the <tracee>;
+ * the same hack is done for <lj_fff_res1>. When the <tracee> hits
+ * the interruption at <lj_fff_res1>, SIGPROF is emitted while
+ * resuming the <tracee>. As a result sysprof collects the full
+ * backtrace with <tostring> fast function as the topmost frame.
+ *
+ * See more info here:
+ * * https://man7.org/linux/man-pages/man2/ptrace.2.html
+ * * https://github.com/tarantool/tarantool/issues/8594
+ * * https://github.com/tarantool/tarantool/issues/9387
+ */
+
+#define MESSAGE "Canary is alive"
+#define LUACALL "local a = tostring('" MESSAGE "') return a"
+/* XXX: Resolve the necessary addresses from VM engine. */
+extern void *lj_ff_tostring(void);
+extern void *lj_fff_res1(void);
+
+/* Sysprof "/dev/null" stream helpers. {{{ */
+
+/*
+ * Yep, 8Mb. Tuned in order not to bother the platform with too
+ * often flushes.
+ */
+#define STREAM_BUFFER_SIZE (8 * 1024 * 1024)
+#define DEVNULL -1
+
+struct devnull_ctx {
+	/*
+	 * XXX: Dummy file descriptor to be used as "/dev/null"
+	 * context indicator in writer and on_stop callback.
+	 */
+	int fd;
+	/* Buffer for data recorded by sysprof. */
+	uint8_t buf[STREAM_BUFFER_SIZE];
+};
+
+static int stream_new(struct luam_Sysprof_Options *options) {
+	struct devnull_ctx *ctx = calloc(1, sizeof(struct devnull_ctx));
+	if (ctx == NULL)
+		return PROFILE_ERRIO;
+
+	/* Set "/dev/null" context indicator. */
+	ctx->fd = DEVNULL;
+	options->ctx = ctx;
+	options->buf = ctx->buf;
+	options->len = STREAM_BUFFER_SIZE;
+
+	return PROFILE_SUCCESS;
+}
+
+static int stream_delete(void *rawctx, uint8_t *buf) {
+	struct devnull_ctx *ctx = rawctx;
+	assert(ctx->fd == DEVNULL);
+	free(ctx);
+	return PROFILE_SUCCESS;
+}
+
+static size_t stream_writer(const void **buf_addr, size_t len, void *rawctx) {
+	struct devnull_ctx *ctx = rawctx;
+	assert(ctx->fd == DEVNULL);
+	/* Do nothing, just return back to the profiler. */
+	return STREAM_BUFFER_SIZE;
+}
+
+/* }}} Sysprof "/dev/null" stream helpers. */
+
+static int tracee(const char *luacode) {
+	struct luam_Sysprof_Counters counters = {};
+	struct luam_Sysprof_Options opt = {
+		/* Collect full backtraces per event. */
+		.mode = LUAM_SYSPROF_CALLGRAPH,
+		/*
+		 * XXX: Setting the "endless timer". The test
+		 * requires the single event to be streamed at
+		 * <lj_fff_res1> instruction, so to avoid spoiling
+		 * the stream with other unwanted events, the
+		 * timer is set to some unreachable point, so the
+		 * profiler will be guaranteed to stop before any
+		 * event is emitted.
+		 */
+		.interval = -1ULL,
+	};
+
+	/* Allow tracing for this process */
+	if (ptrace(PTRACE_TRACEME, 0, 0, 0) < 0) {
+		perror("Failed to turn the calling thread into a tracee");
+		return EXIT_FAILURE;
+	}
+
+	/*
+	 * XXX: Allow parent (which is our tracer now) to observe
+	 * our signal-delivery-stop (i.e. the tracee is ready).
+	 * For more info see ptrace(2), "Attaching and detaching".
+	 */
+	raise(SIGSTOP);
+
+	lua_State *L = utils_lua_init();
+
+	/* Customize and start profiler. */
+	assert(stream_new(&opt) == PROFILE_SUCCESS);
+	assert(luaM_sysprof_set_writer(stream_writer) == PROFILE_SUCCESS);
+	assert(luaM_sysprof_set_on_stop(stream_delete) == PROFILE_SUCCESS);
+	assert(luaM_sysprof_start(L, &opt) == PROFILE_SUCCESS);
+
+	/* FIXME: Make this part test agnostic. */
+	assert(luaL_dostring(L, luacode) == LUA_OK);
+	assert(strcmp(lua_tostring(L, -1), MESSAGE) == 0);
+
+	/* Terminate profiler and Lua universe. */
+	assert(luaM_sysprof_stop(L) == PROFILE_SUCCESS);
+	utils_lua_close(L);
+
+	/*
+	 * XXX: The only event to be streamed must be FFUNC at
+	 * <lj_fff_res1> instruction.
+	 * FIXME: Make this part test agnostic.
+	 */
+	assert(luaM_sysprof_report(&counters) == PROFILE_SUCCESS);
+	assert(counters.samples == 1);
+	assert(counters.vmst_ffunc == 1);
+
+	return EXIT_SUCCESS;
+}
+
+const uint8_t INT3 = 0xCC;
+static inline unsigned long int3poison(unsigned long instruction) {
+	const size_t int3bits = sizeof(INT3) * 8;
+	const unsigned long int3mask = -1UL >> int3bits << int3bits;
+	return (instruction & int3mask) | INT3;
+}
+
+static int continue_until(pid_t chpid, void *addr) {
+	int wstatus;
+	struct user_regs_struct regs;
+
+	/* Obtain the instructions at the <addr>. */
+	unsigned long data = ptrace(PTRACE_PEEKTEXT, chpid, addr, 0);
+	/*
+	 * Emit the <int 3> instruction to the <addr>.
+	 * XXX: <int 3> is poisoned as the LSB to the <data>
+	 * obtained from the <addr> above.
+	 */
+	ptrace(PTRACE_POKETEXT, chpid, addr, int3poison(data));
+
+	/* Resume <chpid> tracee until SIGTRAP occurs. */
+	ptrace(PTRACE_CONT, chpid, 0, 0);
+	/* Wait <chpid> tracee signal-delivery-stop. */
+	waitpid(chpid, &wstatus, 0);
+
+	/* Obtain GPR set to tweak RIP for further execution. */
+	ptrace(PTRACE_GETREGS, chpid, 0, &regs);
+	/*
+	 * Make sure we indeed are stopped at <addr>.
+	 * XXX: RIP points right after <int 3> instruction.
+	 */
+	assert(regs.rip == (long)addr + sizeof(INT3));
+
+	/*
+	 * XXX: Restore the original instruction at <addr> and
+	 * "rewind" RIP by <int 3> size to "replay" the poisoned
+	 * instruction at the <addr>.
+	 */
+	regs.rip -= sizeof(INT3);
+	ptrace(PTRACE_SETREGS, chpid, 0, &regs);
+	ptrace(PTRACE_POKETEXT, chpid, addr, data);
+
+	/* Return wait status to the caller for test checks. */
+	return wstatus;
+}
+
+static int tracer(pid_t chpid) {
+	int wstatus;
+
+	/* Wait until <chpid> tracee is ready. */
+	waitpid(chpid, &wstatus, 0);
+
+	/* Resume <chpid> tracee until <lj_ff_tostring>. */
+	wstatus = continue_until(chpid, lj_ff_tostring);
+
+	/* The tracee has to be alive and stopped by SIGTRAP. */
+	assert_false(WIFEXITED(wstatus));
+	assert_true(WIFSTOPPED(wstatus));
+
+	/* Resume <chpid> tracee until <lj_fff_res1>. */
+	wstatus = continue_until(chpid, lj_fff_res1);
+
+	/* The tracee has to be alive and stopped by SIGTRAP. */
+	assert_false(WIFEXITED(wstatus));
+	assert_true(WIFSTOPPED(wstatus));
+
+	/* Send SIGPROF to make sysprof collect the event. */
+	ptrace(PTRACE_CONT, chpid, 0, SIGPROF);
+
+	/* Wait until <chpid> tracee successfully exits. */
+	waitpid(chpid, &wstatus, 0);
+	assert_true(WIFEXITED(wstatus));
+
+	return TEST_EXIT_SUCCESS;
+}
+
+static int test_tostring_call(void *ctx) {
+	pid_t chpid = fork();
+	switch(chpid) {
+	case -1:
+		bail_out("Tracee fork failed");
+	case 0:
+		/*
+		 * XXX: Tracee has to <exit> instead of <return>
+		 * to avoid duplicate reports in <test_run_group>.
+		 * Test assertions are used only in the <tracer>,
+		 * so the <tracer> ought to report whether the
+		 * test succeeded or not.
+		 */
+		exit(tracee(LUACALL));
+	default:
+		return tracer(chpid);
+	}
+}
+
+#else /* LUAJIT_OS == LUAJIT_OS_LINUX && LUAJIT_TARGET == LUAJIT_ARCH_X64 */
+
+static int test_tostring_call(void *ctx) {
+	return skip_all("sysprof is implemented for Linux/x86_64 only");
+}
+
+#endif /* LUAJIT_OS == LUAJIT_OS_LINUX && LUAJIT_TARGET == LUAJIT_ARCH_X64 */
+
+int main(void) {
+	const struct test_unit tgroup[] = {
+		test_unit_def(test_tostring_call),
+	};
+	return test_run_group(tgroup, NULL);
+}
diff --git a/test/tarantool-tests/gh-8594-sysprof-ffunc-crash.test.lua b/test/tarantool-tests/gh-8594-sysprof-ffunc-crash.test.lua
deleted file mode 100644
index f8b409ae..00000000
--- a/test/tarantool-tests/gh-8594-sysprof-ffunc-crash.test.lua
+++ /dev/null
@@ -1,55 +0,0 @@
-local tap = require('tap')
-local test = tap.test('gh-8594-sysprof-ffunc-crash'):skipcond({
-  ['Sysprof is implemented for x86_64 only'] = jit.arch ~= 'x86' and
-                                               jit.arch ~= 'x64',
-  ['Sysprof is implemented for Linux only'] = jit.os ~= 'Linux',
-  -- luacheck: no global
-  ['Prevent hanging Tarantool CI due to #9387'] = _TARANTOOL,
-})
-
-test:plan(1)
-
-jit.off()
--- XXX: Run JIT tuning functions in a safe frame to avoid errors
--- thrown when LuaJIT is compiled with JIT engine disabled.
-pcall(jit.flush)
-
-local TMP_BINFILE = '/dev/null'
-
--- XXX: The best way to test the issue is to set the profile
--- interval to be as short as possible. However, our CI is
--- not capable of handling such intense testing, so it was a
--- forced decision to reduce the sampling frequency for it. As a
--- result, it is now less likely to reproduce the issue
--- statistically, but the test case is still valid.
-
--- GitHub always sets[1] the `CI` environment variable to `true`
--- for every step in a workflow.
--- [1]: https://docs.github.com/en/actions/learn-github-actions/variables#default-environment-variables
-local CI = os.getenv('CI') == 'true'
-
--- Profile interval and number of iterations for CI are
--- empirical. Non-CI profile interval is set to be as short
--- as possible, so the issue is more likely to reproduce.
--- Non-CI number of iterations is greater for the same reason.
-local PROFILE_INTERVAL = CI and 3 or 1
-local N_ITERATIONS = CI and 1e5 or 1e6
-
-local res, err = misc.sysprof.start{
-  mode = 'C',
-  interval = PROFILE_INTERVAL,
-  path = TMP_BINFILE,
-}
-assert(res, err)
-
-for i = 1, N_ITERATIONS do
-  -- XXX: `tostring` is FFUNC.
-  tostring(i)
-end
-
-res, err = misc.sysprof.stop()
-assert(res, err)
-
-test:ok(true, 'FFUNC frames were streamed correctly')
-
-os.exit(test:check() and 0 or 1)
-- 
2.39.2