From 40654782c980179cb4dc5c144adad4a1c6ea42d9 Mon Sep 17 00:00:00 2001 From: Rasmus Lerdorf Date: Mon, 14 Sep 2026 22:04:14 -0400 Subject: [PATCH 1/3] event_fout: split oversized traces into <= -b byte chunks instead of dropping them A trace that does not fit in the -b buffer is not truncated, it is lost. event_handler_fout_snprintf returns PHPSPY_ERR|PHPSPY_ERR_BUF_FULL, that escapes the FRAME handler through `try`, should_stop_trace aborts the walk, and do_trace_end only runs STACK_END when rv == PHPSPY_OK -- so the write never happens at all, while the log line claims it is "truncating". Because it is depth that overflows the buffer, the samples that disappear are exactly the deep stacks, which is the opposite of what a profiler should drop. At the default -b against a 200-deep recursion, every single sample is lost: phpspy --limit=0 --time-limit-ms=2000 -- php -r \ 'function f($n){ if($n) f($n-1); else usleep(3000000); } f(200);' \ | grep -c '^0 ' 0 # before, default -b 198 # before, -b 65536 198 # after, default -b Rather than truncate and mark, the whole trace is now assembled in a growable per-handler buffer and then split at record boundaries into chunks of at most -b bytes, each written with a single writev(2) and ending in a `# trace_id = ./` record. -b therefore changes meaning from "output buffer size" to "max bytes per write", and defaults to PIPE_BUF rather than a hardcoded 4096: at that size every chunk is still atomic on a pipe, so -P worker threads can only ever interleave whole chunks, and a reader can put a trace back together by id. Nobody has to choose a buffer size any more. Three cases cannot be chunked: a single record longer than a chunk's payload, -1/--single-line mode (where a trace must stay on one line), and the 4 MiB assembly cap. Those emit `# truncated = 1` and STACK_END returns PHPSPY_ERR_BUF_FULL *after* writing, so PHPSPY_TRACE_COUNTED() still counts the sample toward --limit -- previously a truncated sample counted for nothing, and `--limit=N` against a deep stack could never terminate. Also fixed along the way, all in the same code path: The trace delimiter was skipped when the -d epilogue overflowed, silently merging two traces into one. With `-d pt` and a -b just large enough for the frames, every consecutive trace ran together -- 198 traces, 0 blank lines before this change, 198 and 198 after. (The epilogue's try_break did not help: `break` binds to the macro's own do/while, so it never left the block. The block is gone now; the delimiter is written by the chunk writer and no longer depends on anything having fit.) A failed vsnprintf left its partial record in the buffer where the -f/-F filter and the write could see it; the buffer is now re-terminated on every failure path. And the "Not enough space in buffer" line was printed once per record, i.e. dozens of times per sample at 99 Hz; it is now one line per handler for the lifetime of the run. The filter now matches against the whole assembled trace instead of only its first -b bytes, which is the behaviour the flag always implied. -b gains a minimum of 128 so that a chunk always has at least 64 bytes of payload under the 64 bytes reserved for the marker, the delimiters and the truncated record. phpspy_trace.c needs no change: PHPSPY_ERR_BUF_FULL is raised only here, and the handler now absorbs overflow internally, so the walk always completes and STACK_END always runs. Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01V8kSnhaw7WUaR61G6cBp1w --- event_fout.c | 383 ++++++++++++++++++++++++++++---------- phpspy.c | 21 ++- phpspy.h | 14 ++ tests/test_buffer_full.sh | 29 ++- tests/test_truncate.sh | 47 +++++ 5 files changed, 378 insertions(+), 116 deletions(-) create mode 100755 tests/test_truncate.sh diff --git a/event_fout.c b/event_fout.c index c6d3a50..e3c7379 100644 --- a/event_fout.c +++ b/event_fout.c @@ -2,21 +2,29 @@ typedef struct event_handler_fout_udata_s { int fd; - char *buf; - char *cur; - size_t buf_size; - size_t rem; + char *buf; /* assembled trace; always NUL-terminated at buf[used] */ + size_t used; /* payload length, not counting the NUL */ + size_t alloc; /* bytes allocated; always >= used + 1 */ + int single_line; /* -1 mode; chunking is disabled */ + int trunc; /* this trace was truncated; reset at STACK_BEGIN */ + int warned; /* truncation already logged by this handler */ int use_mutex; } event_handler_fout_udata_t; -static int event_handler_fout_write(event_handler_fout_udata_t *udata); -static int event_handler_fout_snprintf(char **s, size_t *n, size_t *ret_len, int repl_delim, const char *fmt, ...); +static int event_handler_fout_flush(event_handler_fout_udata_t *udata); +static size_t event_handler_fout_chunk_end(const char *buf, size_t used, size_t start, size_t cap, int *oversize); +static int event_handler_fout_writev_all(int fd, struct iovec *iov, int iovcnt); +static int event_handler_fout_reserve(event_handler_fout_udata_t *udata, size_t need, size_t limit); +static void event_handler_fout_truncated(event_handler_fout_udata_t *udata); +static void event_handler_fout_vrecord(event_handler_fout_udata_t *udata, size_t limit, int honor_trunc, const char *fmt, va_list vl); +static void event_handler_fout_record(event_handler_fout_udata_t *udata, const char *fmt, ...); +static void event_handler_fout_record_epi(event_handler_fout_udata_t *udata, const char *fmt, ...); static int event_handler_fout_open(int *fd); static pthread_mutex_t event_handler_fout_mutex = PTHREAD_MUTEX_INITIALIZER; +static uint64_t event_handler_fout_trace_id = 0; int event_handler_fout(struct trace_context_s *context, int event_type) { int rv, fd; - size_t len; trace_frame *frame; trace_request *request; event_handler_fout_udata_t *udata; @@ -26,32 +34,36 @@ int event_handler_fout(struct trace_context_s *context, int event_type) { if (!udata && event_type != PHPSPY_TRACE_EVENT_INIT) { return PHPSPY_ERR; } - len = 0; switch (event_type) { case PHPSPY_TRACE_EVENT_INIT: try(rv, event_handler_fout_open(&fd)); udata = calloc(1, sizeof(event_handler_fout_udata_t)); udata->fd = fd; - udata->buf_size = opt_fout_buffer_size + 1; /* + 1 for null char */ - udata->buf = malloc(udata->buf_size); - udata->cur = udata->buf; - udata->rem = udata->buf_size; + udata->alloc = (size_t)opt_fout_buffer_size + 1; /* + 1 for null char */ + udata->buf = malloc(udata->alloc); + if (!udata->buf) { + log_error("event_handler_fout: Failed to allocate %lu bytes\n", (unsigned long)udata->alloc); + close(fd); + free(udata); + return PHPSPY_ERR; + } + udata->used = 0; + udata->buf[0] = '\0'; + udata->single_line = opt_trace_delim != opt_frame_delim ? 1 : 0; udata->use_mutex = context->event_handler_opts != NULL && strchr(context->event_handler_opts, 'm') != NULL ? 1 : 0; context->event_udata = udata; break; case PHPSPY_TRACE_EVENT_STACK_BEGIN: - udata->cur = udata->buf; - udata->cur[0] = '\0'; - udata->rem = udata->buf_size; + /* keep alloc; a per-thread high water mark avoids realloc churn */ + udata->used = 0; + udata->buf[0] = '\0'; + udata->trunc = 0; break; case PHPSPY_TRACE_EVENT_FRAME: frame = &context->event.frame; - try(rv, event_handler_fout_snprintf( - &udata->cur, - &udata->rem, - &len, - 1, + event_handler_fout_record( + udata, "%d %.*s%s%.*s %.*s:%d", frame->depth, (int)frame->loc.class_len, frame->loc.class, @@ -59,63 +71,45 @@ int event_handler_fout(struct trace_context_s *context, int event_type) { (int)frame->loc.func_len, frame->loc.func, (int)frame->loc.file_len, frame->loc.file, frame->loc.lineno - )); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_frame_delim)); + ); break; case PHPSPY_TRACE_EVENT_VARPEEK: - try(rv, event_handler_fout_snprintf( - &udata->cur, - &udata->rem, - &len, - 1, + event_handler_fout_record( + udata, "# varpeek %s@%s = %.*s", context->event.varpeek.var->name, context->event.varpeek.entry->filename_lineno, - context->event.varpeek.zval_str_len, + (int)context->event.varpeek.zval_str_len, context->event.varpeek.zval_str - )); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_frame_delim)); + ); break; case PHPSPY_TRACE_EVENT_GLOPEEK: - try(rv, event_handler_fout_snprintf( - &udata->cur, - &udata->rem, - &len, - 1, + event_handler_fout_record( + udata, "# glopeek %s = %.*s", context->event.glopeek.gentry->key, - context->event.glopeek.zval_str_len, + (int)context->event.glopeek.zval_str_len, context->event.glopeek.zval_str - )); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_frame_delim)); + ); break; case PHPSPY_TRACE_EVENT_REQUEST: request = &context->event.request; - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 1, "# uri = %s", request->uri)); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_frame_delim)); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 1, "# path = %s", request->path)); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_frame_delim)); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 1, "# qstring = %s", request->qstring)); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_frame_delim)); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 1, "# cookie = %s", request->cookie)); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_frame_delim)); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 1, "# ts = %f", request->ts)); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_frame_delim)); + event_handler_fout_record(udata, "# uri = %s", request->uri); + event_handler_fout_record(udata, "# path = %s", request->path); + event_handler_fout_record(udata, "# qstring = %s", request->qstring); + event_handler_fout_record(udata, "# cookie = %s", request->cookie); + event_handler_fout_record(udata, "# ts = %f", request->ts); break; case PHPSPY_TRACE_EVENT_MEM: - try(rv, event_handler_fout_snprintf( - &udata->cur, - &udata->rem, - &len, - 1, + event_handler_fout_record( + udata, "# mem %lu %lu", (uint64_t)context->event.mem.size, (uint64_t)context->event.mem.peak - )); - try(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_frame_delim)); + ); break; case PHPSPY_TRACE_EVENT_STACK_END: - if (udata->cur == udata->buf) { + if (udata->used == 0) { /* buffer is empty */ break; } @@ -124,20 +118,18 @@ int event_handler_fout(struct trace_context_s *context, int event_type) { if (opt_filter_negate == 0 && rv != 0) return PHPSPY_ERR_SKIPPED; if (opt_filter_negate != 0 && rv == 0) return PHPSPY_ERR_SKIPPED; } - do { - if (opt_verbose_fields_ts) { - gettimeofday(&tv, NULL); - try_break(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 1, "# trace_ts = %f", (double)(tv.tv_sec + tv.tv_usec / 1000000.0))); - try_break(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_frame_delim)); - } - if (opt_verbose_fields_pid) { - try_break(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 1, "# pid = %d", context->target.pid)); - try_break(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_frame_delim)); - } - try_break(rv, event_handler_fout_snprintf(&udata->cur, &udata->rem, &len, 0, "%c", opt_trace_delim)); - } while (0); - try(rv, event_handler_fout_write(udata)); - break; + if (opt_verbose_fields_ts) { + gettimeofday(&tv, NULL); + event_handler_fout_record_epi(udata, "# trace_ts = %f", (double)(tv.tv_sec + tv.tv_usec / 1000000.0)); + } + if (opt_verbose_fields_pid) { + event_handler_fout_record_epi(udata, "# pid = %d", context->target.pid); + } + try(rv, event_handler_fout_flush(udata)); + /* the trace was written, so a truncated sample still counts toward + `--limit` via PHPSPY_TRACE_COUNTED. A failed write returns plain + PHPSPY_ERR above and must not count. */ + return udata->trunc ? PHPSPY_ERR_BUF_FULL : PHPSPY_OK; case PHPSPY_TRACE_EVENT_DEINIT: close(udata->fd); free(udata->buf); @@ -147,27 +139,83 @@ int event_handler_fout(struct trace_context_s *context, int event_type) { return PHPSPY_OK; } -static int event_handler_fout_write(event_handler_fout_udata_t *udata) { - int rv; - ssize_t write_len; +/** + * Split the assembled trace into chunks of at most `opt_fout_buffer_size` + * bytes and write each with a single writev(2). + */ +static int event_handler_fout_flush(event_handler_fout_udata_t *udata) { + int rv, oversize, mlen; + unsigned int k, nchunks; + size_t cap, start, end, used; + uint64_t id; + char marker[PHPSPY_FOUT_CHUNK_RESERVE]; + struct iovec iov[2]; - rv = PHPSPY_OK; - write_len = (udata->cur - udata->buf); + cap = (size_t)opt_fout_buffer_size - (size_t)PHPSPY_FOUT_CHUNK_RESERVE; + used = udata->used; + start = 0; + nchunks = 0; - if (write_len < 1) { - /* nothing to write */ - return rv; + /* pass 1: count chunks and settle truncation before the ids are taken */ + while (start < used) { + end = event_handler_fout_chunk_end(udata->buf, used, start, cap, &oversize); + if (oversize) { + /* one record is longer than a chunk; cut it, keep it delimited */ + udata->buf[end - 1] = opt_frame_delim; + event_handler_fout_truncated(udata); + nchunks += 1; + used = end; + break; + } + nchunks += 1; + start = end; + if (udata->single_line && start < used) { + /* a trace must stay on one line, so it cannot be chunked */ + event_handler_fout_truncated(udata); + used = start; + break; + } + } + udata->buf[used] = '\0'; + udata->used = used; + if (udata->trunc) { + event_handler_fout_record_epi(udata, "# truncated = 1"); + used = udata->used; } + /* pass 2: write. The id is taken outside the lock, so ids may reach the + stream slightly out of order; the reader keys on them, not on order. */ + id = __atomic_fetch_add(&event_handler_fout_trace_id, 1, __ATOMIC_RELAXED); + rv = PHPSPY_OK; if (udata->use_mutex) { pthread_mutex_lock(&event_handler_fout_mutex); } - - if (write(udata->fd, udata->buf, write_len) != write_len) { - log_error("event_handler_fout: Write failed (%s)\n", errno != 0 ? strerror(errno) : "partial"); - rv = PHPSPY_ERR; + start = 0; + for (k = 0; k < nchunks; k++) { + /* the last chunk also carries the record appended after pass 1 */ + end = k + 1 == nchunks + ? used + : event_handler_fout_chunk_end(udata->buf, used, start, cap, &oversize); + mlen = snprintf(marker, sizeof(marker), "# trace_id = %llu.%u/%u%c", + (unsigned long long)id, k, nchunks, opt_frame_delim); + if (mlen < 0 || (size_t)mlen + 1 >= sizeof(marker)) { + log_error("event_handler_fout: Failed to format trace_id marker\n"); + rv = PHPSPY_ERR; + break; + } + if (k + 1 == nchunks) { + marker[mlen++] = opt_trace_delim; + } + iov[0].iov_base = udata->buf + start; + iov[0].iov_len = end - start; + iov[1].iov_base = marker; + iov[1].iov_len = (size_t)mlen; + if (event_handler_fout_writev_all(udata->fd, iov, 2) != PHPSPY_OK) { + rv = PHPSPY_ERR; + break; + } + start = end; } - if (udata->use_mutex) { pthread_mutex_unlock(&event_handler_fout_mutex); } @@ -175,34 +223,167 @@ static int event_handler_fout_write(event_handler_fout_udata_t *udata) { return rv; } -static int event_handler_fout_snprintf(char **s, size_t *n, size_t *ret_len, int repl_delim, const char *fmt, ...) { +/** + * Return the end offset of the chunk starting at `start`. The buffer always + * ends with `opt_frame_delim`, so scanning back from the cap lands on a record + * boundary unless a single record is longer than `cap`. + */ +static size_t event_handler_fout_chunk_end(const char *buf, size_t used, size_t start, size_t cap, int *oversize) { + size_t end, i; + + *oversize = 0; + end = start + cap < used ? start + cap : used; + if (end == used) { + return end; + } + for (i = end; i > start; i--) { + if (buf[i - 1] == opt_frame_delim) { + return i; + } + } + *oversize = 1; + return start + cap; +} + +static int event_handler_fout_writev_all(int fd, struct iovec *iov, int iovcnt) { + ssize_t n; + + while (iovcnt > 0) { + n = writev(fd, iov, iovcnt); + if (n < 0) { + if (errno == EINTR) { + continue; + } + log_error("event_handler_fout: Write failed (%s)\n", strerror(errno)); + return PHPSPY_ERR; + } + while (iovcnt > 0 && (size_t)n >= iov->iov_len) { + n -= (ssize_t)iov->iov_len; + iov += 1; + iovcnt -= 1; + } + if (iovcnt > 0) { + iov->iov_base = (char *)iov->iov_base + n; + iov->iov_len -= (size_t)n; + } + } + + return PHPSPY_OK; +} + +/** + * Ensure `need` bytes are available past `used`, growing the buffer up to a + * payload of `limit` bytes. + */ +static int event_handler_fout_reserve(event_handler_fout_udata_t *udata, size_t need, size_t limit) { + size_t alloc; + char *buf; + + if (udata->used + need <= udata->alloc) { + return PHPSPY_OK; + } + if (udata->used + need > limit + 1) { + return PHPSPY_ERR_BUF_FULL; + } + alloc = udata->alloc; + while (alloc < udata->used + need) { + /* clamp before doubling so that `alloc` cannot overflow */ + if (alloc > (limit + 1) / 2) { + alloc = limit + 1; + break; + } + alloc *= 2; + } + buf = realloc(udata->buf, alloc); + if (!buf) { + log_error("event_handler_fout: Failed to allocate %lu bytes\n", (unsigned long)alloc); + return PHPSPY_ERR; + } + udata->buf = buf; + udata->alloc = alloc; + + return PHPSPY_OK; +} + +static void event_handler_fout_truncated(event_handler_fout_udata_t *udata) { + udata->trunc = 1; + if (!udata->warned) { + udata->warned = 1; + log_error( + "event_handler_fout: trace truncated (record exceeds -b payload, " + "single-line mode, or %u-byte trace cap); further truncations not reported\n", + PHPSPY_FOUT_MAX_TRACE + ); + } +} + +/** + * Append one record plus `opt_frame_delim` to the buffer. Body and delimiter + * are appended together so that the buffer always ends with a delimiter, which + * is what lets the chunker find record boundaries by scanning back. + */ +static void event_handler_fout_vrecord(event_handler_fout_udata_t *udata, size_t limit, int honor_trunc, const char *fmt, va_list vl) { int len, i; - va_list vl; char *c; + va_list vl2; - va_start(vl, fmt); - len = vsnprintf(*s, *n, fmt, vl); - va_end(vl); + if (honor_trunc && udata->trunc) { + /* never emit a later record after refusing an earlier one */ + return; + } - if (len < 0 || (size_t)len >= *n) { - log_error("event_handler_fout_snprintf: Not enough space in buffer; truncating\n"); - return PHPSPY_ERR | PHPSPY_ERR_BUF_FULL; + va_copy(vl2, vl); + len = vsnprintf(udata->buf + udata->used, udata->alloc - udata->used, fmt, vl); + if (len < 0) { + udata->buf[udata->used] = '\0'; + event_handler_fout_truncated(udata); + va_end(vl2); + return; + } + if ((size_t)len + 2 > udata->alloc - udata->used) { + /* + 2 for the delimiter and the null char */ + if (event_handler_fout_reserve(udata, (size_t)len + 2, limit) != PHPSPY_OK) { + udata->buf[udata->used] = '\0'; + event_handler_fout_truncated(udata); + va_end(vl2); + return; + } + len = vsnprintf(udata->buf + udata->used, udata->alloc - udata->used, fmt, vl2); + if (len < 0 || (size_t)len + 2 > udata->alloc - udata->used) { + udata->buf[udata->used] = '\0'; + event_handler_fout_truncated(udata); + va_end(vl2); + return; + } } + va_end(vl2); - if (repl_delim) { - for (i = 0; i < len; i++) { /* TODO optimize */ - c = *s + i; - if (*c == opt_trace_delim || *c == opt_frame_delim) { - *c = '?'; - } + for (i = 0; i < len; i++) { /* TODO optimize */ + c = udata->buf + udata->used + i; + if (*c == opt_trace_delim || *c == opt_frame_delim) { + *c = '?'; } } - *s += len; - *n -= len; - *ret_len = (size_t)len; + udata->buf[udata->used + (size_t)len] = opt_frame_delim; + udata->used += (size_t)len + 1; + udata->buf[udata->used] = '\0'; +} - return PHPSPY_OK; +static void event_handler_fout_record(event_handler_fout_udata_t *udata, const char *fmt, ...) { + va_list vl; + + va_start(vl, fmt); + event_handler_fout_vrecord(udata, PHPSPY_FOUT_MAX_TRACE - PHPSPY_FOUT_EPILOGUE_RESERVE, 1, fmt, vl); + va_end(vl); +} + +static void event_handler_fout_record_epi(event_handler_fout_udata_t *udata, const char *fmt, ...) { + va_list vl; + + va_start(vl, fmt); + event_handler_fout_vrecord(udata, PHPSPY_FOUT_MAX_TRACE, 0, fmt, vl); + va_end(vl); } static int event_handler_fout_open(int *fd) { diff --git a/phpspy.c b/phpspy.c index 22ddd14..c9f8392 100644 --- a/phpspy.c +++ b/phpspy.c @@ -16,7 +16,7 @@ regex_t *opt_filter_re = NULL; int opt_filter_negate = 0; int opt_verbose_fields_pid = 0; int opt_verbose_fields_ts = 0; -int opt_fout_buffer_size = 4096; +int opt_fout_buffer_size = PIPE_BUF; char *opt_libname_awk_patt = "libphp[78]?"; int opt_quiet = 0; int opt_peek_pdo = 0; @@ -160,12 +160,15 @@ void usage(FILE *fp, int exit_code) { fprintf(fp, " --addr-sapi-globals= Set address of sapi_globals in hex\n"); fprintf(fp, " (default: %lu; 0=find dynamically)\n", opt_executor_globals_addr); fprintf(fp, " -1, --single-line Output in single-line mode\n"); - fprintf(fp, " -b, --buffer-size= Set output buffer size to `size`.\n"); - fprintf(fp, " Note: In `-P` mode, setting this\n"); - fprintf(fp, " above PIPE_BUF (4096) may lead to\n"); - fprintf(fp, " interlaced writes across threads\n"); - fprintf(fp, " unless `-J m` is specified.\n"); - fprintf(fp, " (default: %d)\n", opt_fout_buffer_size); + fprintf(fp, " -b, --buffer-size= Set max bytes per write to `size`.\n"); + fprintf(fp, " Traces larger than this are split into\n"); + fprintf(fp, " chunks, each ending with a\n"); + fprintf(fp, " `# trace_id = ./` record.\n"); + fprintf(fp, " Note: In `-P` mode, setting this above\n"); + fprintf(fp, " PIPE_BUF (4096) may lead to interlaced\n"); + fprintf(fp, " writes across threads unless\n"); + fprintf(fp, " `--event-handler-opts m` is specified.\n"); + fprintf(fp, " (min: %d; default: %d)\n", PHPSPY_FOUT_MIN_BUFFER, opt_fout_buffer_size); fprintf(fp, " -f, --filter= Filter output by POSIX regex\n"); fprintf(fp, " (default: none)\n"); fprintf(fp, " -F, --filter-negate= Same as `-f` except negated\n"); @@ -327,7 +330,7 @@ static void parse_opts(int argc, char **argv) { case PHPSPY_LONGOPT_ADDR_EXECUTOR_GLOBALS: opt_executor_globals_addr = strtoull(optarg, NULL, 16); break; case PHPSPY_LONGOPT_ADDR_SAPI_GLOBALS: opt_sapi_globals_addr = strtoull(optarg, NULL, 16); break; case '1': opt_frame_delim = '\t'; opt_trace_delim = '\n'; break; - case 'b': opt_fout_buffer_size = atoi_with_min_or_exit("-b", optarg, 1); break; + case 'b': opt_fout_buffer_size = atoi_with_min_or_exit("-b", optarg, PHPSPY_FOUT_MIN_BUFFER); break; case 'f': case 'F': if (opt_filter_re) { @@ -478,7 +481,7 @@ int main_pid(pid_t pid) { } /* maybe apply trace limit */ - if (opt_trace_limit > 0 && rv == PHPSPY_OK) { + if (opt_trace_limit > 0 && PHPSPY_TRACE_COUNTED(rv)) { if (in_pgrep_mode) { __atomic_add_fetch(&trace_count, 1, __ATOMIC_SEQ_CST); } else { diff --git a/phpspy.h b/phpspy.h index 16fc0f0..f60baf0 100644 --- a/phpspy.h +++ b/phpspy.h @@ -55,6 +55,20 @@ #define PHPSPY_HASH_FLAG_PACKED (1 << 2) #define PHPSPY_MAX_STACK_WALK 1024 +/* event_fout: max assembled payload bytes for one trace */ +#define PHPSPY_FOUT_MAX_TRACE (4u * 1024u * 1024u) +/* bytes kept free under the cap for the `-d` fields and the truncated record */ +#define PHPSPY_FOUT_EPILOGUE_RESERVE 256 +/* per-chunk bytes reserved for the trace_id marker, delimiters and the + truncated record: `# trace_id = ` (13) + 20 digits + `.` + 5 + `/` + 5 = 45, + + frame delim + trace delim = 47; `# truncated = 1` (15) + frame delim = 16 */ +#define PHPSPY_FOUT_CHUNK_RESERVE 64 +/* -b minimum; leaves at least PHPSPY_FOUT_CHUNK_RESERVE bytes of payload */ +#define PHPSPY_FOUT_MIN_BUFFER 128 + +/* a truncated trace is still written, so it counts toward `--limit` */ +#define PHPSPY_TRACE_COUNTED(__rv) ((__rv) == PHPSPY_OK || ((__rv) & PHPSPY_ERR_BUF_FULL) != 0) + enum { PHPSPY_OK = 0, PHPSPY_ERR = 1 << 0, diff --git a/tests/test_buffer_full.sh b/tests/test_buffer_full.sh index 5de9f0f..8873bca 100755 --- a/tests/test_buffer_full.sh +++ b/tests/test_buffer_full.sh @@ -1,16 +1,33 @@ #!/bin/bash # shellcheck disable=SC2034 # ignore seemingly unused test_invoke params +# shellcheck disable=SC2016 # ignore $var in single quote strings # shellcheck source=/dev/null source "$TEST_SH" -test_phpspy_opts=(--continue-on-error --buffer-size=24 -- "${PHP[@]}" -r 'usleep(1000000);') +php_src='function f($n){ if($n) f($n-1); else usleep(2000000); } f(20);' +# --limit=1 would race with the child's startup, whose stack is only `
`; +# sample for a while instead and assert over the whole capture +sample=(--limit=0 --time-limit-ms=1500) + +# a deep trace no longer fits in one 128-byte write, but nothing is dropped +test_phpspy_opts=("${sample[@]}" --buffer-size=128 -- "${PHP[@]}" -r "$php_src") +declare -A test_expected test_not_expected +test_expected[frame_0 ]='^0 usleep :-1$' +test_expected[frame_22 ]='^22
' +test_expected[marker ]='^# trace_id = \d+\.\d+/\d+$' +test_expected[continuation ]='^# trace_id = \d+\.[1-9]\d*/\d+$' +test_not_expected[no_trunc ]='^# truncated' +test_invoke + +# filter still applies to the whole assembled trace, before chunking +test_phpspy_opts=("${sample[@]}" --buffer-size=128 --filter '
' -- "${PHP[@]}" -r "$php_src") declare -A test_expected -declare -A test_not_expected -test_expected[frame_0 ]='^0 usleep :-1$' -test_not_expected[no_frame_1 ]='^1
:-1$' +test_expected[filtered_frame_0]='^0 usleep :-1$' +test_expected[filtered_marker ]='^# trace_id = \d+\.\d+/\d+$' test_invoke -test_phpspy_opts=(--buffer-size=24 -- "${PHP[@]}" -r 'usleep(1000000);') +test_phpspy_opts=("${sample[@]}" --buffer-size=128 --filter 'nomatch_xyz' -- "${PHP[@]}" -r "$php_src") declare -A test_not_expected -test_not_expected[anything]='^.+$' +test_not_expected[filtered_out_all]='^.+$' +test_use_timeout_s=10 test_invoke diff --git a/tests/test_truncate.sh b/tests/test_truncate.sh new file mode 100755 index 0000000..bfeff88 --- /dev/null +++ b/tests/test_truncate.sh @@ -0,0 +1,47 @@ +#!/bin/bash +# shellcheck disable=SC2034 # ignore seemingly unused test_invoke params +# shellcheck disable=SC2016 # ignore $var in single quote strings +# shellcheck source=/dev/null +source "$TEST_SH" + +long_fn="f$(printf 'x%.0s' $(seq 1 200))" + +# one frame line is longer than a 128-byte chunk's 64-byte payload +_run_single_record() { + local raw out rc blanks depth0 + # capture to a file: command substitution would eat the trailing blank line + raw=$(mktemp) + # --limit=5: only the child's startup sample can avoid truncation, so if a + # BUF_FULL sample did not count toward the limit this would run until the + # timeout killed it + timeout 10 "$PHPSPY" --limit=5 --child-stdout=/dev/null --child-stderr=/dev/null \ + --buffer-size=128 -- "${PHP[@]}" -r "function ${long_fn}(){ usleep(2000000); } ${long_fn}();" \ + >"$raw" 2>/dev/null + rc=$? + out=$(cat "$raw") + depth0=$(grep -c '^0 ' "$raw") + blanks=$(grep -c '^$' "$raw") + rm -f "$raw" + test_assert "trunc_limit_terminates" "0" "$rc" # BUF_FULL sample counted toward --limit + test_assert_re "trunc_marker" '^# truncated = 1$' "$out" + test_assert_re "trunc_chunk_marker" '^# trace_id = \d+\.\d+/\d+$' "$out" + test_assert "trunc_one_delim_per_trace" "$depth0" "$blanks" # delimiter guarantee +} +test_fn=_run_single_record +test_invoke + +# single-line mode: chunking disabled, one line per trace, marked truncated. +# NOTE: in -1 mode the tab is the *trailing* record delimiter; lines still start with "0 ". +_run_single_line() { + local out lines depth0 + out=$(timeout 10 "$PHPSPY" --limit=0 --time-limit-ms=1000 \ + --child-stdout=/dev/null --child-stderr=/dev/null -1 --buffer-size=128 \ + -- "${PHP[@]}" -r 'function f($n){ if($n) f($n-1); else usleep(2000000); } f(20);' 2>/dev/null) + lines=$(grep -c . <<<"$out") + depth0=$(grep -c '^0 ' <<<"$out") + test_assert "single_line_one_line_per_trace" "$lines" "$depth0" + test_assert_re "single_line_truncated" '# truncated = 1' "$out" + test_assert_re "single_line_marker" '# trace_id = \d+\.0/1' "$out" +} +test_fn=_run_single_line +test_invoke From 2abe3a3d10186a25888fba2004e0004e440b9bbf Mon Sep 17 00:00:00 2001 From: Rasmus Lerdorf Date: Mon, 14 Sep 2026 22:07:51 -0400 Subject: [PATCH 2/3] stackcollapse-phpspy.pl: reassemble chunked traces by trace_id A trace larger than -b is now written as several chunks, and in -P mode chunks belonging to different traces can be interleaved in the stream. The script flushed on every depth-0 frame, so an interleaved capture would attribute the second half of one process's stack to the other's and produce stacks that never existed. It now keys on the `# trace_id = ./` record that terminates every chunk. Frames accumulate into a pending list, a marker moves that list onto its id's partial stack, and the final chunk (k == n-1) emits the whole thing. This is sound because each chunk's payload and its marker are written with a single writev(2) that is atomic on a pipe at the default -b, so the frame lines immediately preceding a marker always belong to that marker's id no matter how many threads are writing. Files captured before this change have no markers, so the old depth-0 flush is kept and used until the first marker is seen -- which, on chunked input, is before any depth-0 line other than the first. Once markers are in play, a leftover pending list or an unterminated id is a partial stack and is dropped rather than counted as a short one; a chunk that arrives with an unexpected index discards its id, warns once, and leaves other traces alone. tests/test.sh exposes its sudo/timeout prefix as `test_cmd_prefix`, because the harness does not wrap `test_fn` tests itself and test_chunk_interleave.sh has to attach to live pids. Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01V8kSnhaw7WUaR61G6cBp1w --- stackcollapse-phpspy.pl | 62 +++++++++++++++++++++++++++++----- tests/test.sh | 15 +++++--- tests/test_chunk_interleave.sh | 50 +++++++++++++++++++++++++++ tests/test_stackcollapse.sh | 53 +++++++++++++++++++++++++++++ 4 files changed, 166 insertions(+), 14 deletions(-) create mode 100755 tests/test_chunk_interleave.sh create mode 100755 tests/test_stackcollapse.sh diff --git a/stackcollapse-phpspy.pl b/stackcollapse-phpspy.pl index c9558da..048b0e9 100755 --- a/stackcollapse-phpspy.pl +++ b/stackcollapse-phpspy.pl @@ -14,19 +14,26 @@ # 1 aaa /home/mlauter/profiling/sample.php:5 # 2 bbb /home/mlauter/profiling/sample.php:10 # 3
/home/mlauter/profiling/sample.php:25 -# # - - - +# # trace_id = 0.0/1 +# # 0 sleep :-1 # 1 aaa /home/mlauter/profiling/sample.php:5 # 2
/home/mlauter/profiling/sample.php:28 -# # - - - +# # trace_id = 1.0/1 +# # 0 sleep :-1 # 1 aaa /home/mlauter/profiling/sample.php:5 # 2 bbb /home/mlauter/profiling/sample.php:10 # 3 ccc /home/mlauter/profiling/sample.php:15 # 4
/home/mlauter/profiling/sample.php:22 -# # - - - +# # trace_id = 2.0/1 +# # ... # +# A trace larger than phpspy's -b is written as several chunks, each ending in +# its own `# trace_id = ./` record. In -P mode chunks of different +# traces may be interleaved in the stream; they are reassembled here by id. +# # Example Output: #
;ccc;bbb;aaa 1 #
;aaa 1 @@ -58,9 +65,43 @@ sub usage { # internals my %stacks; -my @frames; +my @pending; # funcs of the current, not-yet-terminated chunk +my %open; # trace id => [ funcs accumulated so far ] +my %expect; # trace id => next expected chunk index +my %bad; # trace id => 1 once warned +my $seen_marker = 0; while (defined(my $line = <>)) { + chomp $line; + + # must be tested before the generic record filter below, which a marker + # would otherwise match + if ($line =~ m{^# trace_id = (\d+)\.(\d+)/(\d+)$}) { + my ($id, $k, $m) = ($1, $2, $3); + $seen_marker = 1; + my $want = exists $expect{$id} ? $expect{$id} : 0; + if ($k != $want) { + warn "stackcollapse-phpspy: trace $id: expected chunk $want, got $k; discarding\n" + unless $bad{$id}; + $bad{$id} = 1; + delete $open{$id}; + delete $expect{$id}; + @pending = (); + delete $bad{$id} if $k == $m - 1; + next; + } + push @{$open{$id}}, @pending; + @pending = (); + $expect{$id} = $k + 1; + if ($k == $m - 1) { + $stacks{join(';', reverse @{$open{$id}})} += 1 if @{$open{$id}}; + delete $open{$id}; + delete $expect{$id}; + delete $bad{$id}; + } + next; + } + next unless $line =~ /^(?:#|\d+) \S/; my ($depth, $func) = (split ' ', $line)[0,1]; @@ -75,14 +116,17 @@ sub usage { # turn it back into a string $func = encode("utf-8", $func); - if ($depth ne '#' && $depth == 0) { - $stacks{join(';', reverse @frames)} += 1 if @frames; - @frames = (); + # legacy (pre-trace_id) input: flush on each depth-0 frame + if (!$seen_marker && $depth ne '#' && $depth == 0) { + $stacks{join(';', reverse @pending)} += 1 if @pending; + @pending = (); } - push @frames, $func if $line =~ /^\d/; + push @pending, $func if $line =~ /^\d/; } -$stacks{join(';', reverse @frames)} += 1 if @frames; +# legacy input only: flush the tail. With markers, @pending and every +# incomplete %open entry are partial stacks and are discarded. +$stacks{join(';', reverse @pending)} += 1 if @pending && !$seen_marker; while ( my ($k, $v) = each %stacks ) { print "$k $v\n"; diff --git a/tests/test.sh b/tests/test.sh index 9e77a08..0cb455d 100644 --- a/tests/test.sh +++ b/tests/test.sh @@ -29,7 +29,12 @@ test_invoke() { declare -gA test_expected test_not_expected declare -ga test_phpspy_opts - local cmd_prefix=() actual exit_code testname + local actual exit_code testname + + # global so that a `test_fn` test, which the harness does not wrap itself, + # can apply the same sudo/timeout prefix + declare -ga test_cmd_prefix + test_cmd_prefix=() if [ -n "$test_need_ptrace" ]; then local ptrace_scope @@ -39,12 +44,12 @@ test_invoke() { elif getcap "$PHPSPY" 2>/dev/null | grep -q cap_sys_ptrace; then : elif sudo -n true &>/dev/null; then - cmd_prefix+=(sudo -n) + test_cmd_prefix+=(sudo -n) else test_skip='need ptrace' fi fi - [ -n "$test_use_timeout_s" ] && cmd_prefix+=(timeout "$test_use_timeout_s") + [ -n "$test_use_timeout_s" ] && test_cmd_prefix+=(timeout "$test_use_timeout_s") if [ -n "$test_skip" ]; then echo -e " \x1b[33mSKIP\x1b[0m $test_skip" @@ -52,7 +57,7 @@ test_invoke() { "$test_fn" else actual=$( - "${cmd_prefix[@]}" "$PHPSPY" \ + "${test_cmd_prefix[@]}" "$PHPSPY" \ --limit=1 \ --child-stdout=/dev/null \ --child-stderr=/dev/null \ @@ -77,7 +82,7 @@ test_invoke() { done fi - unset test_phpspy_opts test_expected test_not_expected test_need_ptrace test_use_timeout_s test_skip test_non_zero_ok test_fn + unset test_cmd_prefix test_phpspy_opts test_expected test_not_expected test_need_ptrace test_use_timeout_s test_skip test_non_zero_ok test_fn } test_init diff --git a/tests/test_chunk_interleave.sh b/tests/test_chunk_interleave.sh new file mode 100755 index 0000000..17058ad --- /dev/null +++ b/tests/test_chunk_interleave.sh @@ -0,0 +1,50 @@ +#!/bin/bash +# shellcheck disable=SC2034 # ignore seemingly unused test_invoke params +# shellcheck disable=SC2016 # ignore $var in single quote strings +# shellcheck disable=SC2154 # test_cmd_prefix is assigned by the sourced test.sh +# shellcheck source=/dev/null +source "$TEST_SH" + +repo=$(dirname "$(dirname "$TEST_SH")") + +_run_interleave() { + local a_pid b_pid collapsed mixed + # The token lives in each child's argv (inside a PHP comment). The pgrep pattern + # spells it with a bracket so that neither phpspy's own argv nor the `sh -c pgrep ...` + # child (both of which contain the bracketed form) matches itself. + "${PHP[@]}" -r '/*phpspy_ilv_token*/ function aaaa_f($n){ if($n) aaaa_f($n-1); else usleep(3000000); } aaaa_f(40);' >/dev/null 2>&1 & + a_pid=$! + "${PHP[@]}" -r '/*phpspy_ilv_token*/ function bbbb_f($n){ if($n) bbbb_f($n-1); else usleep(3000000); } bbbb_f(40);' >/dev/null 2>&1 & + b_pid=$! + sleep 0.3 + collapsed=$("${test_cmd_prefix[@]}" "$PHPSPY" -P '-f phpspy_ilv_toke[n]' --threads 2 \ + --buffer-size=512 --time-limit-ms=2000 --limit=0 2>/dev/null \ + | "$repo/stackcollapse-phpspy.pl" 2>/dev/null) + wait "$a_pid" "$b_pid" + test_assert_re "interleave_saw_aaaa" '(^|;)aaaa_f' "$collapsed" + test_assert_re "interleave_saw_bbbb" '(^|;)bbbb_f' "$collapsed" + mixed=$(grep -cP '^(?=.*aaaa_f)(?=.*bbbb_f)' <<<"$collapsed") + test_assert "interleave_no_mixed_stacks" "0" "$mixed" + test_assert "interleave_no_partial_stacks" "0" "$(grep -cv '^
' <<<"$collapsed")" +} +test_need_ptrace=1 +test_use_timeout_s=15 +test_fn=_run_interleave +test_invoke + +# round-trip: no sample lost, no stack cut short +_run_roundtrip() { + local raw collapsed n_traces n_collapsed + raw=$(mktemp) + timeout 10 "$PHPSPY" --limit=0 --time-limit-ms=2000 --buffer-size=256 \ + --child-stdout=/dev/null --child-stderr=/dev/null \ + -- "${PHP[@]}" -r 'function f($n){ if($n) f($n-1); else usleep(3000000); } f(40);' >"$raw" 2>/dev/null + collapsed=$("$repo/stackcollapse-phpspy.pl" <"$raw") + n_traces=$(grep -c '^0 ' "$raw") + n_collapsed=$(awk '{s+=$NF} END{print s+0}' <<<"$collapsed") + rm -f "$raw" + test_assert "roundtrip_no_sample_lost" "$n_traces" "$n_collapsed" + test_assert "roundtrip_no_partial_stacks" "0" "$(grep -cv '^
' <<<"$collapsed")" +} +test_fn=_run_roundtrip +test_invoke diff --git a/tests/test_stackcollapse.sh b/tests/test_stackcollapse.sh new file mode 100755 index 0000000..0b375b5 --- /dev/null +++ b/tests/test_stackcollapse.sh @@ -0,0 +1,53 @@ +#!/bin/bash +# shellcheck disable=SC2034 # ignore seemingly unused test_invoke params +# shellcheck source=/dev/null +source "$TEST_SH" + +repo=$(dirname "$(dirname "$TEST_SH")") + +_run_fixtures() { + local out + # two traces whose chunks interleave: A.0 B.0 A.1 B.1 + out=$("$repo/stackcollapse-phpspy.pl" <<'EOF' | sort +0 aaa /t.php:1 +1 bbb /t.php:2 +# trace_id = 1.0/2 +0 ccc /t.php:1 +1 ddd /t.php:2 +# trace_id = 2.0/2 +2
/t.php:3 +# trace_id = 1.1/2 + +3
/t.php:4 +# trace_id = 2.1/2 + +EOF +) + test_assert "interleaved_chunks" "$(printf '
;bbb;aaa 1\n
;ddd;ccc 1')" "$out" + + # pre-trace_id capture files still collapse + out=$("$repo/stackcollapse-phpspy.pl" <<'EOF' | sort +0 aaa /t.php:1 +1
/t.php:2 + +0 aaa /t.php:1 +1
/t.php:2 + +EOF +) + test_assert "legacy_no_markers" "
;aaa 2" "$out" + + # a chunk arriving out of order is discarded, later traces are unaffected + out=$("$repo/stackcollapse-phpspy.pl" 2>/dev/null <<'EOF' +0 aaa /t.php:1 +# trace_id = 9.1/2 +0 zzz /t.php:1 +1
/t.php:2 +# trace_id = 8.0/1 + +EOF +) + test_assert "out_of_order_chunk_discarded" "
;zzz 1" "$out" +} +test_fn=_run_fixtures +test_invoke From 04ff89d729184b16cbadc9aa2a62fe1786a06c89 Mon Sep 17 00:00:00 2001 From: Rasmus Lerdorf Date: Mon, 14 Sep 2026 22:08:54 -0400 Subject: [PATCH 3/3] docs: document chunked output and fix the stale trace separator The README showed `# - - - - -` between traces in three examples. phpspy has never emitted that; the separator is a blank line, so anyone writing a parser from the README got it wrong. The examples now show what the tool actually prints, including the `# trace_id` record that terminates every trace. Adds an "Output format" section, since the record grammar was only discoverable by running the thing, and it now matters: a reader has to know that a trace can arrive as several chunks and that in `-P` mode the chunks of different traces can be interleaved, which is what stackcollapse-phpspy.pl is for. `-b` is described as "max bytes per write" to match usage(). Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01V8kSnhaw7WUaR61G6cBp1w --- README.md | 43 +++++++++++++++++++++++++++++++++++-------- 1 file changed, 35 insertions(+), 8 deletions(-) diff --git a/README.md b/README.md index 11c56f6..a7cf263 100644 --- a/README.md +++ b/README.md @@ -103,12 +103,15 @@ All with no changes to your application and minimal overhead. --addr-sapi-globals= Set address of sapi_globals in hex (default: 0; 0=find dynamically) -1, --single-line Output in single-line mode - -b, --buffer-size= Set output buffer size to `size`. - Note: In `-P` mode, setting this - above PIPE_BUF (4096) may lead to - interlaced writes across threads - unless `-J m` is specified. - (default: 4096) + -b, --buffer-size= Set max bytes per write to `size`. + Traces larger than this are split into + chunks, each ending with a + `# trace_id = ./` record. + Note: In `-P` mode, setting this above + PIPE_BUF (4096) may lead to interlaced + writes across threads unless + `--event-handler-opts m` is specified. + (min: 128; default: 4096) -f, --filter= Filter output by POSIX regex (default: none) -F, --filter-negate= Same as `-f` except negated @@ -150,6 +153,22 @@ All with no changes to your application and minimal overhead. e.g., server.REQUEST_TIME -t, --top Show dynamic top-like output +### Output format + +Each trace is a sequence of records separated by a newline (a tab with `-1`), +followed by a blank line. Frame records are ` :`; +metadata records start with `#`. Every trace ends with a +`# trace_id = ./` record: `` is a per-process trace counter, +`` the 0-based index of this chunk and `` the number of chunks the trace +was split into. A trace larger than `-b` bytes is split at record boundaries +into `` chunks, each written with a single `writev(2)` so that it is atomic +on a pipe; in `-P` mode chunks belonging to different traces may therefore be +interleaved in the stream, and `./stackcollapse-phpspy.pl` (which reassembles +by `trace_id`) must be used to collapse such output. A `# truncated = 1` record +means the rest of the trace was dropped: a single record longer than `-b` minus +64 bytes, `-1/--single-line` mode (where chunking is disabled), or a trace above +the 4 MiB assembly cap. + ### Example (variable peek) $ sudo ./phpspy -e 'i@/var/www/test/lib/test.php:12' -p $(pgrep -n httpd) | grep varpeek @@ -167,7 +186,8 @@ All with no changes to your application and minimal overhead. 2 run_test /home/adam/php-src/run-tests.php:1937 3 run_all_tests /home/adam/php-src/run-tests.php:1215 4
/home/adam/php-src/run-tests.php:986 - # - - - - - + # trace_id = 0.0/1 + ... ^C main_pgrep finished gracefully @@ -190,7 +210,8 @@ All with no changes to your application and minimal overhead. 12 Security_Rule_Engine::evaluateActionRules /foo/bar/lib/Security/Rule/Engine.php:116 13
/foo/bar/lib/bootstrap/api.php:49 14
/foo/bar/htdocs/v3/public.php:5 - # - - - - - + # trace_id = 0.0/1 + ... ### Example (cli child) @@ -198,21 +219,27 @@ All with no changes to your application and minimal overhead. $ ./phpspy -- php -r 'usleep(100000);' 0 usleep :-1 1
:-1 + # trace_id = 0.0/1 0 usleep :-1 1
:-1 + # trace_id = 1.0/1 0 usleep :-1 1
:-1 + # trace_id = 2.0/1 0 usleep :-1 1
:-1 + # trace_id = 3.0/1 0 usleep :-1 1
:-1 + # trace_id = 4.0/1 0 usleep :-1 1
:-1 + # trace_id = 5.0/1 process_vm_readv: No such process