Skip to content

Commit b48b905

Browse files
committed
test: rewrite sysprof test using managed execution
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 285a1b0 ("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 fef60a1 ("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
1 parent eda99db commit b48b905

File tree

2 files changed

+269
-55
lines changed

2 files changed

+269
-55
lines changed
Lines changed: 269 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,269 @@
1+
#include "lauxlib.h"
2+
#include "lmisclib.h"
3+
#include "lua.h"
4+
5+
#include "test.h"
6+
#include "utils.h"
7+
8+
#include <signal.h>
9+
#include <sys/ptrace.h>
10+
#include <sys/user.h>
11+
#include <sys/wait.h>
12+
#include <unistd.h>
13+
14+
/* XXX: Still need normal assert inside <tracee> and helpers. */
15+
#undef NDEBUG
16+
#include <assert.h>
17+
18+
/*
19+
* XXX: The test is *very* Linux/x86_64 specific. Fortunately, so
20+
* does the sampling profiler. <lj_arch.> is needed for LUAJIT_OS
21+
* and LUAJIT_TARGET.
22+
*/
23+
#include "lj_arch.h"
24+
25+
#if LUAJIT_OS == LUAJIT_OS_LINUX && LUAJIT_TARGET == LUAJIT_ARCH_X64
26+
27+
/*
28+
* XXX: The test makes sysprof to collect the particular event
29+
* (FFUNC) at the particular instruction (<lj_fff_res1>) to
30+
* reproduce the issue #8594. Hence it's enough to call <tostring>
31+
* fast function (this is done in <tracee> function). To emit
32+
* SIGPROF right at <lj_fff_res1> in scope of <tostring> fast
33+
* function, the managed execution is implemented in the function
34+
* <tracer>: <int 3> instruction is poisoned as the first
35+
* instruction at <lj_ff_tostring> to stop <tracee> at the
36+
* beginning of the fast function; <tracer> resumes the <tracee>;
37+
* the same hack is done for <lj_fff_res1>. When the <tracee> hits
38+
* the interruption at <lj_fff_res1>, SIGPROF is emitted while
39+
* resuming the <tracee>. As a result sysprof collects the full
40+
* backtrace with <tostring> fast function as the topmost frame.
41+
*
42+
* See more info here:
43+
* * https://man7.org/linux/man-pages/man2/ptrace.2.html
44+
* * https://github.com/tarantool/tarantool/issues/8594
45+
* * https://github.com/tarantool/tarantool/issues/9387
46+
*/
47+
48+
#define MESSAGE "Canary is alive"
49+
#define LUACALL "local a = tostring('" MESSAGE "') return a"
50+
/* XXX: Resolve the necessary addresses from VM engine. */
51+
extern void *lj_ff_tostring(void);
52+
extern void *lj_fff_res1(void);
53+
54+
/* Sysprof "/dev/null" stream helpers. {{{ */
55+
56+
/*
57+
* Yep, 8Mb. Tuned in order not to bother the platform with too
58+
* often flushes.
59+
*/
60+
#define STREAM_BUFFER_SIZE (8 * 1024 * 1024)
61+
#define DEVNULL -1
62+
63+
struct devnull_ctx {
64+
/*
65+
* XXX: Dummy file descriptor to be used as "/dev/null"
66+
* context indicator in writer and on_stop callback.
67+
*/
68+
int fd;
69+
/* Buffer for data recorded by sysprof. */
70+
uint8_t buf[STREAM_BUFFER_SIZE];
71+
};
72+
73+
static int stream_new(struct luam_Sysprof_Options *options) {
74+
struct devnull_ctx *ctx = calloc(1, sizeof(struct devnull_ctx));
75+
if (ctx == NULL)
76+
return PROFILE_ERRIO;
77+
78+
/* Set "/dev/null" context indicator. */
79+
ctx->fd = DEVNULL;
80+
options->ctx = ctx;
81+
options->buf = ctx->buf;
82+
options->len = STREAM_BUFFER_SIZE;
83+
84+
return PROFILE_SUCCESS;
85+
}
86+
87+
static int stream_delete(void *rawctx, uint8_t *buf) {
88+
struct devnull_ctx *ctx = rawctx;
89+
assert(ctx->fd == DEVNULL);
90+
free(ctx);
91+
return PROFILE_SUCCESS;
92+
}
93+
94+
static size_t stream_writer(const void **buf_addr, size_t len, void *rawctx) {
95+
struct devnull_ctx *ctx = rawctx;
96+
assert(ctx->fd == DEVNULL);
97+
/* Do nothing, just return back to the profiler. */
98+
return STREAM_BUFFER_SIZE;
99+
}
100+
101+
/* }}} Sysprof "/dev/null" stream helpers. */
102+
103+
static int tracee(const char *luacode) {
104+
struct luam_Sysprof_Counters counters = {};
105+
struct luam_Sysprof_Options opt = {
106+
/* Collect full backtraces per event. */
107+
.mode = LUAM_SYSPROF_CALLGRAPH,
108+
/*
109+
* XXX: Setting the "endless timer". The test
110+
* requires the single event to be streamed at
111+
* <lj_fff_res1> instruction, so to avoid spoiling
112+
* the stream with other unwanted events, the
113+
* timer is set to some unreachable point, so the
114+
* profiler will be guaranteed to stop before any
115+
* event is emitted.
116+
*/
117+
.interval = -1ULL,
118+
};
119+
120+
/* Allow tracing for this process */
121+
if (ptrace(PTRACE_TRACEME, 0, 0, 0) < 0) {
122+
perror("Failed to turn the calling thread into a tracee");
123+
return EXIT_FAILURE;
124+
}
125+
126+
/*
127+
* XXX: Allow parent (which is our tracer now) to observe
128+
* our signal-delivery-stop (i.e. the tracee is ready).
129+
* For more info see ptrace(2), "Attaching and detaching".
130+
*/
131+
raise(SIGSTOP);
132+
133+
lua_State *L = utils_lua_init();
134+
135+
/* Customize and start profiler. */
136+
assert(stream_new(&opt) == PROFILE_SUCCESS);
137+
assert(luaM_sysprof_set_writer(stream_writer) == PROFILE_SUCCESS);
138+
assert(luaM_sysprof_set_on_stop(stream_delete) == PROFILE_SUCCESS);
139+
assert(luaM_sysprof_start(L, &opt) == PROFILE_SUCCESS);
140+
141+
/* FIXME: Make this part test agnostic. */
142+
assert(luaL_dostring(L, luacode) == LUA_OK);
143+
assert(strcmp(lua_tostring(L, -1), MESSAGE) == 0);
144+
145+
/* Terminate profiler and Lua universe. */
146+
assert(luaM_sysprof_stop(L) == PROFILE_SUCCESS);
147+
utils_lua_close(L);
148+
149+
/*
150+
* XXX: The only event to be streamed must be FFUNC at
151+
* <lj_fff_res1> instruction.
152+
* FIXME: Make this part test agnostic.
153+
*/
154+
assert(luaM_sysprof_report(&counters) == PROFILE_SUCCESS);
155+
assert(counters.samples == 1);
156+
assert(counters.vmst_ffunc == 1);
157+
158+
return EXIT_SUCCESS;
159+
}
160+
161+
const uint8_t INT3 = 0xCC;
162+
static inline unsigned long int3poison(unsigned long instruction) {
163+
const size_t int3bits = sizeof(INT3) * 8;
164+
const unsigned long int3mask = -1UL >> int3bits << int3bits;
165+
return (instruction & int3mask) | INT3;
166+
}
167+
168+
static int continue_until(pid_t chpid, void *addr) {
169+
int wstatus;
170+
struct user_regs_struct regs;
171+
172+
/* Obtain the instructions at the <addr>. */
173+
unsigned long data = ptrace(PTRACE_PEEKTEXT, chpid, addr, 0);
174+
/*
175+
* Emit the <int 3> instruction to the <addr>.
176+
* XXX: <int 3> is poisoned as the LSB to the <data>
177+
* obtained from the <addr> above.
178+
*/
179+
ptrace(PTRACE_POKETEXT, chpid, addr, int3poison(data));
180+
181+
/* Resume <chpid> tracee until SIGTRAP occurs. */
182+
ptrace(PTRACE_CONT, chpid, 0, 0);
183+
/* Wait <chpid> tracee signal-delivery-stop. */
184+
waitpid(chpid, &wstatus, 0);
185+
186+
/* Obtain GPR set to tweak RIP for further execution. */
187+
ptrace(PTRACE_GETREGS, chpid, 0, &regs);
188+
/*
189+
* Make sure we indeed are stopped at <addr>.
190+
* XXX: RIP points right after <int 3> instruction.
191+
*/
192+
assert(regs.rip == (long)addr + sizeof(INT3));
193+
194+
/*
195+
* XXX: Restore the original instruction at <addr> and
196+
* "rewind" RIP by <int 3> size to "replay" the poisoned
197+
* instruction at the <addr>.
198+
*/
199+
regs.rip -= sizeof(INT3);
200+
ptrace(PTRACE_SETREGS, chpid, 0, &regs);
201+
ptrace(PTRACE_POKETEXT, chpid, addr, data);
202+
203+
/* Return wait status to the caller for test checks. */
204+
return wstatus;
205+
}
206+
207+
static int tracer(pid_t chpid) {
208+
int wstatus;
209+
210+
/* Wait until <chpid> tracee is ready. */
211+
waitpid(chpid, &wstatus, 0);
212+
213+
/* Resume <chpid> tracee until <lj_ff_tostring>. */
214+
wstatus = continue_until(chpid, lj_ff_tostring);
215+
216+
/* The tracee has to be alive and stopped by SIGTRAP. */
217+
assert_false(WIFEXITED(wstatus));
218+
assert_true(WIFSTOPPED(wstatus));
219+
220+
/* Resume <chpid> tracee until <lj_fff_res1>. */
221+
wstatus = continue_until(chpid, lj_fff_res1);
222+
223+
/* The tracee has to be alive and stopped by SIGTRAP. */
224+
assert_false(WIFEXITED(wstatus));
225+
assert_true(WIFSTOPPED(wstatus));
226+
227+
/* Send SIGPROF to make sysprof collect the event. */
228+
ptrace(PTRACE_CONT, chpid, 0, SIGPROF);
229+
230+
/* Wait until <chpid> tracee successfully exits. */
231+
waitpid(chpid, &wstatus, 0);
232+
assert_true(WIFEXITED(wstatus));
233+
234+
return TEST_EXIT_SUCCESS;
235+
}
236+
237+
static int test_tostring_call(void *ctx) {
238+
pid_t chpid = fork();
239+
switch(chpid) {
240+
case -1:
241+
bail_out("Tracee fork failed");
242+
case 0:
243+
/*
244+
* XXX: Tracee has to <exit> instead of <return>
245+
* to avoid duplicate reports in <test_run_group>.
246+
* Test assertions are used only in the <tracer>,
247+
* so the <tracer> ought to report whether the
248+
* test succeeded or not.
249+
*/
250+
exit(tracee(LUACALL));
251+
default:
252+
return tracer(chpid);
253+
}
254+
}
255+
256+
#else /* LUAJIT_OS == LUAJIT_OS_LINUX && LUAJIT_TARGET == LUAJIT_ARCH_X64 */
257+
258+
static int test_tostring_call(void *ctx) {
259+
return skip_all("sysprof is implemented for Linux/x86_64 only");
260+
}
261+
262+
#endif /* LUAJIT_OS == LUAJIT_OS_LINUX && LUAJIT_TARGET == LUAJIT_ARCH_X64 */
263+
264+
int main(void) {
265+
const struct test_unit tgroup[] = {
266+
test_unit_def(test_tostring_call),
267+
};
268+
return test_run_group(tgroup, NULL);
269+
}

test/tarantool-tests/gh-8594-sysprof-ffunc-crash.test.lua

Lines changed: 0 additions & 55 deletions
This file was deleted.

0 commit comments

Comments
 (0)