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 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/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_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_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 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