diff --git a/Makefile b/Makefile index 03cacc0..a560a03 100644 --- a/Makefile +++ b/Makefile @@ -10,6 +10,8 @@ prefix?=/usr/local php_cmd?=php -n +test_name?= + sinclude config.mk has_phpconf := $(shell command -v php-config >/dev/null 2>&1 && echo :) @@ -39,6 +41,7 @@ test: phpspy $(phpspy_tests) @total=0; \ pass=0; \ for t in $(phpspy_tests); do \ + test -n "$(test_name)" && test "$$t" != "$(test_name)" && continue; \ tput bold; echo TEST $$t; tput sgr0; \ PHPSPY=./phpspy PHP="$(php_cmd)" TEST_SH=$$(dirname $$t)/test.sh ./$$t; ec=$$?; echo; \ [ $$ec -eq 0 ] && pass=$$((pass+1)); \ diff --git a/README.md b/README.md index 11c56f6..f002515 100644 --- a/README.md +++ b/README.md @@ -92,22 +92,30 @@ All with no changes to your application and minimal overhead. -m, --memory-usage Capture peak and current memory usage with each trace (requires target PHP process to have debug symbols) - -o, --output= Write phpspy output to `path` + -o, --output= Write phpspy output to `path`. If a + `%d` is present, replace it with a + thread id. Useful in `-P` mode. (default: -; -=stdout) - -O, --child-stdout= Write child stdout to `path` - (default: phpspy.%d.out) + -O, --child-stdout= Write child stdout to `path`. + Replace `%d` with child pid. + (default: phpspy.%d.out; -=stdout) -E, --child-stderr= Write child stderr to `path` - (default: phpspy.%d.err) + Replace `%d` with child pid. + (default: phpspy.%d.err; -=stderr) --addr-executor-globals= Set address of executor_globals in hex (default: 0; 0=find dynamically) --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. + -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. + In `-P` mode, if writing to stdout, + setting this above `PIPE_BUF` (4096) + may lead to interleaved writes, + unless `--event-handler-opts m` is + specified. (default: 4096) -f, --filter= Filter output by POSIX regex (default: none) @@ -150,6 +158,23 @@ 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 delimited by newlines (or tabs in `-1` +mode), followed by a newline. Frame records look like +` :`. Metadata records start with a hash (`#`). + +If a trace exceeds `-b` bytes, it is split into multiple chunks at record +boundaries. Each chunk ends with a `# trace_id = .` metadata +record where `` is a process-wide counter, `` is a 0-based index, and +`` is either an exclamation point (`!`) for the last chunk, or a tilde +(`~`) for intermediate chunks. + +If a single record is too large to fit in a chunk, or if a whole trace exceeds +4 megabytes, the trace is truncated. That record and every record after it are +dropped, and the trace ends with a final chunk containing only a +`# truncated = 1` metadata record. + ### Example (variable peek) $ sudo ./phpspy -e 'i@/var/www/test/lib/test.php:12' -p $(pgrep -n httpd) | grep varpeek @@ -167,7 +192,7 @@ 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 - # - - - - - + ... ^C main_pgrep finished gracefully @@ -190,12 +215,12 @@ 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 - # - - - - - + ... ### Example (cli child) - $ ./phpspy -- php -r 'usleep(100000);' + $ ./phpspy -- php -r 'usleep(1000000);' 0 usleep :-1 1
:-1 @@ -213,8 +238,8 @@ All with no changes to your application and minimal overhead. 0 usleep :-1 1
:-1 - - process_vm_readv: No such process + ... + main_pid: pid 2830271 exited ### Example (cli attach) @@ -234,15 +259,16 @@ All with no changes to your application and minimal overhead. ### Known bugs -* phpspy may not work with a chrooted mod_php process whose binary lives inside overlayfs. (See [#109][8].) -* Tracing on aarch64 (arm64) will fail except for on PHP 8.4. +* phpspy may not work with a chrooted mod_php process whose binary lives inside + overlayfs. (See [#109][8].) +* Tracing on aarch64 (arm64) will fail for PHP 8.2 and below. ### See also * [rbspy][0] for Ruby, the original inspiration for phpspy * [py-spy][1] for Python * [Xdebug profiler][2], instrumented profiler -* [php-profiler][3], similar to phpspy but pure PHP +* [reli-prof][3], similar to phpspy but pure PHP * [sample_prof][4] * [php-trace][5] * [Blackfire][6], commercial @@ -256,7 +282,7 @@ All with no changes to your application and minimal overhead. [0]: https://github.com/rbspy/rbspy [1]: https://github.com/benfred/py-spy [2]: http://www.xdebug.org/docs/profiler -[3]: https://github.com/sj-i/php-profiler +[3]: https://github.com/reliforp/reli-prof [4]: https://github.com/nikic/sample_prof [5]: https://github.com/krakjoe/trace [6]: https://blackfire.io/ diff --git a/addr_objdump.c b/addr_objdump.c index 80ec8ea..e4f95e3 100644 --- a/addr_objdump.c +++ b/addr_objdump.c @@ -1,5 +1,4 @@ #include "phpspy.h" -#include static int get_php_bin_path(pid_t pid, char *path_root, char *path); static int get_php_base_addr(pid_t pid, char *path_root, char *path, uint64_t *raddr); diff --git a/event_fout.c b/event_fout.c index c6d3a50..0213e66 100644 --- a/event_fout.c +++ b/event_fout.c @@ -3,20 +3,34 @@ typedef struct event_handler_fout_udata_s { int fd; char *buf; - char *cur; - size_t buf_size; - size_t rem; + size_t len; + size_t cap; int use_mutex; + int truncated; + char trunc_marker[32]; + char trace_id_tail[64]; + size_t trunc_marker_len; + size_t trace_id_tail_len; } 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_write_whole(event_handler_fout_udata_t *udata); +static int event_handler_fout_write_chunked(event_handler_fout_udata_t *udata); +static int event_handler_fout_write_chunk(event_handler_fout_udata_t *udata, char *body, size_t body_len, char sentinel); +static char *event_handler_fout_find_chunk_end(char *chunk_start, char *stop, size_t max_chunk_len); +static void event_handler_fout_fill_trace_id(event_handler_fout_udata_t *udata, uint64_t trace_id, uint64_t chunk_idx); +static void event_handler_fout_iov_set(struct iovec *iov, void *base, size_t len); +static int event_handler_fout_writev(int fd, struct iovec *iov, int iovcnt); +static void event_handler_fout_snprintf(event_handler_fout_udata_t *udata, int strip_delim, const char *fmt, ...); +static void event_handler_fout_truncate(event_handler_fout_udata_t *udata); +static int event_handler_fout_realloc(event_handler_fout_udata_t *udata, size_t needed_cap); 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; +static int event_handler_fout_shared_fd = -1; 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,31 +40,33 @@ 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->cap = opt_fout_buffer_size; + try(rv, event_handler_fout_realloc(udata, udata->cap)); udata->use_mutex = context->event_handler_opts != NULL && strchr(context->event_handler_opts, 'm') != NULL ? 1 : 0; + udata->trunc_marker_len = (size_t)snprintf( + udata->trunc_marker, + sizeof(udata->trunc_marker), + "# truncated = 1%c", + opt_frame_delim + ); context->event_udata = udata; break; case PHPSPY_TRACE_EVENT_STACK_BEGIN: - udata->cur = udata->buf; - udata->cur[0] = '\0'; - udata->rem = udata->buf_size; + udata->len = 0; + udata->buf[0] = '\0'; + udata->truncated = 0; break; case PHPSPY_TRACE_EVENT_FRAME: frame = &context->event.frame; - try(rv, event_handler_fout_snprintf( - &udata->cur, - &udata->rem, - &len, + event_handler_fout_snprintf( + udata, 1, "%d %.*s%s%.*s %.*s:%d", frame->depth, @@ -59,66 +75,57 @@ 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)); + ); + event_handler_fout_snprintf(udata, 0, "%c", opt_frame_delim); break; case PHPSPY_TRACE_EVENT_VARPEEK: - try(rv, event_handler_fout_snprintf( - &udata->cur, - &udata->rem, - &len, + event_handler_fout_snprintf( + udata, 1, "# varpeek %s@%s = %.*s", context->event.varpeek.var->name, context->event.varpeek.entry->filename_lineno, 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)); + ); + event_handler_fout_snprintf(udata, 0, "%c", opt_frame_delim); break; case PHPSPY_TRACE_EVENT_GLOPEEK: - try(rv, event_handler_fout_snprintf( - &udata->cur, - &udata->rem, - &len, + event_handler_fout_snprintf( + udata, 1, "# glopeek %s = %.*s", context->event.glopeek.gentry->key, 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)); + ); + event_handler_fout_snprintf(udata, 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_snprintf(udata, 1, "# uri = %s", request->uri); + event_handler_fout_snprintf(udata, 0, "%c", opt_frame_delim); + event_handler_fout_snprintf(udata, 1, "# path = %s", request->path); + event_handler_fout_snprintf(udata, 0, "%c", opt_frame_delim); + event_handler_fout_snprintf(udata, 1, "# qstring = %s", request->qstring); + event_handler_fout_snprintf(udata, 0, "%c", opt_frame_delim); + event_handler_fout_snprintf(udata, 1, "# cookie = %s", request->cookie); + event_handler_fout_snprintf(udata, 0, "%c", opt_frame_delim); + event_handler_fout_snprintf(udata, 1, "# ts = %f", request->ts); + event_handler_fout_snprintf(udata, 0, "%c", opt_frame_delim); break; case PHPSPY_TRACE_EVENT_MEM: - try(rv, event_handler_fout_snprintf( - &udata->cur, - &udata->rem, - &len, + event_handler_fout_snprintf( + udata, 1, "# 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)); + ); + event_handler_fout_snprintf(udata, 0, "%c", opt_frame_delim); break; case PHPSPY_TRACE_EVENT_STACK_END: - if (udata->cur == udata->buf) { - /* buffer is empty */ - break; - } + if (udata->len == 0) break; if (opt_filter_re) { rv = regexec(opt_filter_re, udata->buf, 0, NULL, 0); if (opt_filter_negate == 0 && rv != 0) return PHPSPY_ERR_SKIPPED; @@ -127,19 +134,20 @@ int event_handler_fout(struct trace_context_s *context, int event_type) { 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)); + event_handler_fout_snprintf(udata, 1, "# trace_ts = %f", (double)(tv.tv_sec + tv.tv_usec / 1000000.0)); + event_handler_fout_snprintf(udata, 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)); + event_handler_fout_snprintf(udata, 1, "# pid = %d", context->target.pid); + event_handler_fout_snprintf(udata, 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; case PHPSPY_TRACE_EVENT_DEINIT: - close(udata->fd); + if (udata->fd != event_handler_fout_shared_fd) { + close(udata->fd); + } free(udata->buf); free(udata); break; @@ -149,100 +157,281 @@ int event_handler_fout(struct trace_context_s *context, int event_type) { static int event_handler_fout_write(event_handler_fout_udata_t *udata) { int rv; - ssize_t write_len; - - rv = PHPSPY_OK; - write_len = (udata->cur - udata->buf); + size_t total_len; - if (write_len < 1) { - /* nothing to write */ - return rv; - } + total_len = udata->len + 1; /* +1 for trace_delim */ + if (udata->truncated) total_len += udata->trunc_marker_len; 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; + if (total_len <= (size_t)opt_fout_buffer_size) { + rv = event_handler_fout_write_whole(udata); + } else { + rv = event_handler_fout_write_chunked(udata); } if (udata->use_mutex) { pthread_mutex_unlock(&event_handler_fout_mutex); } + if (udata->truncated) rv |= PHPSPY_ERR_TRUNCATED; + + return rv; +} + +static int event_handler_fout_write_whole(event_handler_fout_udata_t *udata) { + struct iovec iov[3]; + int iovcnt; + + iovcnt = 0; + event_handler_fout_iov_set(&iov[iovcnt++], udata->buf, udata->len); + if (udata->truncated) { + event_handler_fout_iov_set(&iov[iovcnt++], udata->trunc_marker, udata->trunc_marker_len); + } + event_handler_fout_iov_set(&iov[iovcnt++], &opt_trace_delim, 1); + + return event_handler_fout_writev(udata->fd, iov, iovcnt); +} + +static int event_handler_fout_write_chunked(event_handler_fout_udata_t *udata) { + uint64_t trace_id, chunk_idx; + char *chunk_start, *chunk_end, *stop; + size_t max_chunk_len; + char sentinel; + int rv; + + rv = PHPSPY_OK; + trace_id = __atomic_fetch_add(&event_handler_fout_trace_id, 1, __ATOMIC_RELAXED); + chunk_idx = 0; + chunk_start = udata->buf; + stop = udata->buf + udata->len; + + while (chunk_start < stop) { + /* calc max_chunk_len */ + event_handler_fout_fill_trace_id(udata, trace_id, chunk_idx); + max_chunk_len = (size_t)opt_fout_buffer_size > udata->trace_id_tail_len + ? (size_t)opt_fout_buffer_size - udata->trace_id_tail_len + : 0; + + /* find chunk_end */ + chunk_end = event_handler_fout_find_chunk_end(chunk_start, stop, max_chunk_len); + + /* break if single record exceeds max_chunk_len */ + if (!chunk_end) break; + + /* set sentinel according to whether this is the last chunk */ + sentinel = chunk_end == stop && !udata->truncated ? '!' : '~'; + + rv |= event_handler_fout_write_chunk(udata, chunk_start, (size_t)(chunk_end - chunk_start), sentinel); + + chunk_start = chunk_end; + chunk_idx += 1; + } + + if (chunk_start < stop) udata->truncated = 1; + + if (!udata->truncated) return rv; + + /* write truncated metadata record */ + event_handler_fout_fill_trace_id(udata, trace_id, chunk_idx); + rv |= event_handler_fout_write_chunk(udata, udata->trunc_marker, udata->trunc_marker_len, '!'); + return rv; } -static int event_handler_fout_snprintf(char **s, size_t *n, size_t *ret_len, int repl_delim, const char *fmt, ...) { - int len, i; +static int event_handler_fout_write_chunk(event_handler_fout_udata_t *udata, char *body, size_t body_len, char sentinel) { + struct iovec iov[2]; + + event_handler_fout_iov_set(&iov[0], body, body_len); + + /* set sentinel in trace_id_tail. see event_handler_fout_fill_trace_id + for format. trace_id_tail_len should always be >= 3 */ + assert(udata->trace_id_tail_len >= 3); + udata->trace_id_tail[udata->trace_id_tail_len - 3] = sentinel; + event_handler_fout_iov_set(&iov[1], udata->trace_id_tail, udata->trace_id_tail_len); + + return event_handler_fout_writev(udata->fd, iov, 2); +} + +static char *event_handler_fout_find_chunk_end(char *chunk_start, char *stop, size_t max_chunk_len) { + char *last_delim; + + if ((size_t)(stop - chunk_start) <= max_chunk_len) { + return stop; + } + + last_delim = memrchr(chunk_start, opt_frame_delim, max_chunk_len); + if (!last_delim) { + return NULL; + } + + return last_delim + 1; +} + +static void event_handler_fout_fill_trace_id(event_handler_fout_udata_t *udata, uint64_t trace_id, uint64_t chunk_idx) { + udata->trace_id_tail_len = (size_t)snprintf( + udata->trace_id_tail, + sizeof(udata->trace_id_tail), + "# trace_id = %" PRIu64 ".%" PRIu64 "~%c%c", + trace_id, + chunk_idx, + opt_frame_delim, + opt_trace_delim + ); +} + +static void event_handler_fout_iov_set(struct iovec *iov, void *base, size_t len) { + iov->iov_base = base; + iov->iov_len = len; +} + +static int event_handler_fout_writev(int fd, struct iovec *iov, int iovcnt) { + size_t total_len; + int i; + + total_len = 0; + for (i = 0; i < iovcnt; i++) { + total_len += iov[i].iov_len; + } + + if (writev(fd, iov, iovcnt) != (ssize_t)total_len) { + log_error("event_handler_fout_writev: writev (%s)\n", errno != 0 ? strerror(errno) : "partial"); + return PHPSPY_ERR; + } + + return PHPSPY_OK; +} + +static void event_handler_fout_snprintf(event_handler_fout_udata_t *udata, int strip_delim, const char *fmt, ...) { + int append_len, i; va_list vl; - char *c; + char *delim, *cur, *stop; + size_t rem_cap; + char delims[2] = { opt_frame_delim, opt_trace_delim }; + + if (udata->truncated) return; va_start(vl, fmt); - len = vsnprintf(*s, *n, fmt, vl); + rem_cap = udata->cap - udata->len; + append_len = vsnprintf(udata->buf + udata->len, rem_cap, fmt, vl); va_end(vl); - 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; + if (append_len < 0) { + log_perror("event_handler_fout_snprintf: vsnprintf"); + event_handler_fout_truncate(udata); + return; + } + + if ((size_t)append_len >= rem_cap) { + if (event_handler_fout_realloc(udata, udata->len + (size_t)append_len + 1) != PHPSPY_OK) { + event_handler_fout_truncate(udata); + return; + } + + va_start(vl, fmt); + rem_cap = udata->cap - udata->len; + append_len = vsnprintf(udata->buf + udata->len, rem_cap, fmt, vl); + va_end(vl); } - if (repl_delim) { - for (i = 0; i < len; i++) { /* TODO optimize */ - c = *s + i; - if (*c == opt_trace_delim || *c == opt_frame_delim) { - *c = '?'; + if (strip_delim) { + cur = udata->buf + udata->len; + stop = cur + append_len; + for (i = 0; i < 2; i++) { + while (cur < stop) { + delim = memchr(cur, delims[i], (size_t)(stop - cur)); + if (!delim) break; + *delim = '?'; + cur = delim + 1; } } } - *s += len; - *n -= len; - *ret_len = (size_t)len; + udata->len += (size_t)append_len; +} + +static void event_handler_fout_truncate(event_handler_fout_udata_t *udata) { + char *last_delim; + + udata->truncated = 1; + + last_delim = memrchr(udata->buf, opt_frame_delim, udata->len); + udata->len = last_delim ? (size_t)(last_delim + 1 - udata->buf) : 0; + udata->buf[udata->len] = '\0'; +} + +static int event_handler_fout_realloc(event_handler_fout_udata_t *udata, size_t needed_cap) { + size_t new_cap; + char *new_buf; + + if (needed_cap > PHPSPY_FOUT_MAX_BUFFER) { + return PHPSPY_ERR; + } + + new_cap = udata->cap; + while (new_cap < needed_cap) { + new_cap *= 2; + } + if (new_cap > PHPSPY_FOUT_MAX_BUFFER) { + new_cap = PHPSPY_FOUT_MAX_BUFFER; + } + + new_buf = realloc(udata->buf, new_cap); + if (!new_buf) { + log_perror("event_handler_fout_realloc: realloc"); + return PHPSPY_ERR; + } + + udata->buf = new_buf; + udata->cap = new_cap; return PHPSPY_OK; } static int event_handler_fout_open(int *fd) { - int tfd = -1, errno_saved; - char *path, *apath = NULL; - - if (strcmp(opt_path_output, "-") == 0) { - tfd = dup(STDOUT_FILENO); - if (tfd < 0) { - log_perror("event_handler_fout_open: dup"); - return PHPSPY_ERR; - } - *fd = tfd; - return PHPSPY_OK; - } + int tfd = -1, errno_saved, rv, flags, mode; + char *apath = NULL; + + rv = PHPSPY_OK; + flags = O_WRONLY | O_CREAT | O_TRUNC; + mode = S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH; + + pthread_mutex_lock(&event_handler_fout_mutex); if (strstr(opt_path_output, "%d") != NULL) { if (asprintf(&apath, opt_path_output, gettid()) < 0) { errno = ENOMEM; log_perror("event_handler_fout_open: asprintf"); - return PHPSPY_ERR; + rv = PHPSPY_ERR; + goto event_handler_fout_open_end; } - path = apath; - } else { - path = opt_path_output; - } - - tfd = open(path, O_WRONLY | O_CREAT | O_TRUNC, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH); - errno_saved = errno; - - if (apath) { + tfd = open(apath, flags, mode); + errno_saved = errno; free(apath); + } else { + if (strcmp(opt_path_output, "-") == 0) { + tfd = dup(STDOUT_FILENO); + } else if (event_handler_fout_shared_fd < 0) { + tfd = open(opt_path_output, flags, mode); + event_handler_fout_shared_fd = tfd; + } else { + tfd = dup(event_handler_fout_shared_fd); + } + errno_saved = errno; } if (tfd < 0) { errno = errno_saved; log_perror("event_handler_fout_open: open"); - return PHPSPY_ERR; + rv = PHPSPY_ERR; + goto event_handler_fout_open_end; } *fd = tfd; - return PHPSPY_OK; + +event_handler_fout_open_end: + pthread_mutex_unlock(&event_handler_fout_mutex); + return rv; } diff --git a/pgrep.c b/pgrep.c index cff9ffc..3c2b339 100644 --- a/pgrep.c +++ b/pgrep.c @@ -1,12 +1,12 @@ #include "phpspy.h" static int wait_for_turn(char producer_or_consumer); -static void pgrep_for_pids(); +static void pgrep_for_pids(void); static void *run_work_thread(void *arg); static int is_already_attached(int pid); -static void init_work_threads(); -static void deinit_work_threads(); -static int block_all_signals(); +static void init_work_threads(void); +static void deinit_work_threads(void); +static int block_all_signals(void); static void handle_signal(int signum); static void *run_signal_thread(void *arg); @@ -20,7 +20,7 @@ static pthread_cond_t can_produce = PTHREAD_COND_INITIALIZER; static pthread_cond_t can_consume = PTHREAD_COND_INITIALIZER; static int done_pipe[2] = { -1, -1 }; -int main_pgrep() { +int main_pgrep(void) { long i; if (opt_num_workers < 1) { @@ -78,7 +78,7 @@ static int wait_for_turn(char producer_or_consumer) { return 0; } -static void pgrep_for_pids() { +static void pgrep_for_pids(void) { FILE *pcmd; char *pgrep_cmd; char line[64]; @@ -145,7 +145,7 @@ static int is_already_attached(int pid) { return 0; } -static void init_work_threads() { +static void init_work_threads(void) { avail_pids = calloc(opt_num_workers, sizeof(int)); attached_pids = calloc(opt_num_workers, sizeof(int)); work_threads = calloc(opt_num_workers, sizeof(pthread_t)); @@ -159,7 +159,7 @@ static void init_work_threads() { pthread_cond_init(&can_consume, NULL); } -static void deinit_work_threads() { +static void deinit_work_threads(void) { free(avail_pids); free(attached_pids); free(work_threads); @@ -168,7 +168,7 @@ static void deinit_work_threads() { pthread_cond_destroy(&can_consume); } -static int block_all_signals() { +static int block_all_signals(void) { int rv; sigset_t set; try(rv, sigfillset(&set)); @@ -176,7 +176,7 @@ static int block_all_signals() { return 0; } -void write_done_pipe() { +void write_done_pipe(void) { int rv, ignore; if (done_pipe[1] >= 0) { ignore = 1; diff --git a/phpspy.c b/phpspy.c index 22ddd14..250827e 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; @@ -51,7 +51,7 @@ static uint64_t trace_count = 0; static void parse_opts(int argc, char **argv); static int main_fork(int argc, char **argv); -static void cleanup(); +static void cleanup(void); static int pause_pid(pid_t pid); static int unpause_pid(pid_t pid); static void redirect_child_stdio(int proc_fd, char *opt_path); @@ -149,22 +149,30 @@ void usage(FILE *fp, int exit_code) { fprintf(fp, " -m, --memory-usage Capture peak and current memory usage\n"); fprintf(fp, " with each trace (requires target PHP\n"); fprintf(fp, " process to have debug symbols)\n"); - fprintf(fp, " -o, --output= Write phpspy output to `path`\n"); + fprintf(fp, " -o, --output= Write phpspy output to `path`. If a\n"); + fprintf(fp, " `%%d` is present, replace it with a\n"); + fprintf(fp, " thread id. Useful in `-P` mode.\n"); fprintf(fp, " (default: %s; -=stdout)\n", opt_path_output); - fprintf(fp, " -O, --child-stdout= Write child stdout to `path`\n"); - fprintf(fp, " (default: %s)\n", opt_path_child_out); + fprintf(fp, " -O, --child-stdout= Write child stdout to `path`.\n"); + fprintf(fp, " Replace `%%d` with child pid.\n"); + fprintf(fp, " (default: %s; -=stdout)\n", opt_path_child_out); fprintf(fp, " -E, --child-stderr= Write child stderr to `path`\n"); - fprintf(fp, " (default: %s)\n", opt_path_child_err); + fprintf(fp, " Replace `%%d` with child pid.\n"); + fprintf(fp, " (default: %s; -=stderr)\n", opt_path_child_err); fprintf(fp, " --addr-executor-globals= Set address of executor_globals in hex\n"); fprintf(fp, " (default: %lu; 0=find dynamically)\n", opt_sapi_globals_addr); 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, " -b, --buffer-size= Set max bytes per write to `size`.\n"); + fprintf(fp, " Traces larger than this are split\n"); + fprintf(fp, " into chunks, each ending with a\n"); + fprintf(fp, " `# trace_id = .` record.\n"); + fprintf(fp, " In `-P` mode, if writing to stdout,\n"); + fprintf(fp, " setting this above `PIPE_BUF` (4096)\n"); + fprintf(fp, " may lead to interleaved writes,\n"); + fprintf(fp, " unless `--event-handler-opts m` is\n"); + fprintf(fp, " specified.\n"); fprintf(fp, " (default: %d)\n", opt_fout_buffer_size); fprintf(fp, " -f, --filter= Filter output by POSIX regex\n"); fprintf(fp, " (default: none)\n"); @@ -477,8 +485,8 @@ int main_pid(pid_t pid) { break; } - /* maybe apply trace limit */ - if (opt_trace_limit > 0 && rv == PHPSPY_OK) { + /* maybe apply trace limit. truncated records count. */ + if (opt_trace_limit > 0 && (rv == PHPSPY_OK || rv == PHPSPY_ERR_TRUNCATED)) { if (in_pgrep_mode) { __atomic_add_fetch(&trace_count, 1, __ATOMIC_SEQ_CST); } else { @@ -561,7 +569,7 @@ static int main_fork(int argc, char **argv) { return rv; } -static void cleanup() { +static void cleanup(void) { varpeek_entry *entry, *entry_tmp; varpeek_var *var, *var_tmp; glopeek_entry *gentry, *gentry_tmp; @@ -626,6 +634,7 @@ static void redirect_child_stdio(int proc_fd, char *opt_path) { exit(1); } } + /* TODO open once under mutex and dup for other threads */ if ((redir_file = fopen(redir_path, "w")) == NULL) { log_error( "redirect_child_stdio: Failed to open '%s' for child %s (%s)\n", diff --git a/phpspy.h b/phpspy.h index 16fc0f0..be3263b 100644 --- a/phpspy.h +++ b/phpspy.h @@ -25,10 +25,12 @@ #include #include #include +#include #include #include #include #include +#include #include #ifndef gettid @@ -54,13 +56,14 @@ #define PHPSPY_MAX_ARRAY_TABLE_SIZE 512 #define PHPSPY_HASH_FLAG_PACKED (1 << 2) #define PHPSPY_MAX_STACK_WALK 1024 +#define PHPSPY_FOUT_MAX_BUFFER (4u * 1024u * 1024u) enum { - PHPSPY_OK = 0, - PHPSPY_ERR = 1 << 0, - PHPSPY_ERR_PID_DEAD = 1 << 1, - PHPSPY_ERR_BUF_FULL = 1 << 2, - PHPSPY_ERR_SKIPPED = 1 << 3, + PHPSPY_OK = 0, + PHPSPY_ERR = 1 << 0, + PHPSPY_ERR_PID_DEAD = 1 << 1, + PHPSPY_ERR_TRUNCATED = 1 << 2, + PHPSPY_ERR_SKIPPED = 1 << 3, }; enum { @@ -212,7 +215,7 @@ extern long opt_time_limit_ms; extern char *opt_libname_awk_patt; extern int opt_peek_pdo; -extern int main_pgrep(); +extern int main_pgrep(void); extern int main_pid(pid_t pid); extern int main_top(int argc, char **argv); @@ -220,7 +223,7 @@ extern void usage(FILE *fp, int exit_code); extern int get_symbol_addr(addr_memo *memo, pid_t pid, const char *symbol, uint64_t *raddr); extern int event_handler_fout(struct trace_context_s *context, int event_type); extern int event_handler_callgrind(struct trace_context_s *context, int event_type); -extern void write_done_pipe(); +extern void write_done_pipe(void); extern void log_error(const char *fmt, ...); extern void log_perror(const char *s); extern int shell_escape(const char *arg, char *buf, size_t buf_size, const char *what); diff --git a/phpspy_trace.c b/phpspy_trace.c index 2711d22..87df1f3 100644 --- a/phpspy_trace.c +++ b/phpspy_trace.c @@ -820,7 +820,7 @@ static int sprint_pdo_bind(trace_context *context, zval *lzval, char *buf, size_ #define PHPSPY_TRACE_ONCE static int should_stop_trace(int rv) { return (rv & PHPSPY_ERR_PID_DEAD) != 0 - || (rv & PHPSPY_ERR_BUF_FULL) != 0 + || (rv & PHPSPY_ERR_TRUNCATED) != 0 || (rv != PHPSPY_OK && !opt_continue_on_error); } #endif diff --git a/stackcollapse-phpspy.pl b/stackcollapse-phpspy.pl index c9558da..e14c25b 100755 --- a/stackcollapse-phpspy.pl +++ b/stackcollapse-phpspy.pl @@ -2,9 +2,9 @@ # # stackcolllapse-phpspy.pl collapse phpspy samples into single lines. # -# Parses php samples generated by phpspy and outputs stacks as -# single lines, with methods separated by semicolons, and then a space and an -# occurrence count. For use with flamegraph.pl. +# Parses PHP samples generated by phpspy and outputs stacks as single lines, +# with methods separated by semicolons, and then a space and an occurrence +# count. For use with flamegraph.pl. # # USAGE: ./stackcollapse-phpspy.pl infile > outfile # @@ -14,17 +14,17 @@ # 1 aaa /home/mlauter/profiling/sample.php:5 # 2 bbb /home/mlauter/profiling/sample.php:10 # 3
/home/mlauter/profiling/sample.php:25 -# # - - - +# # 0 sleep :-1 # 1 aaa /home/mlauter/profiling/sample.php:5 # 2
/home/mlauter/profiling/sample.php:28 -# # - - - +# # 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 -# # - - - +# # ... # # Example Output: @@ -58,31 +58,58 @@ sub usage { # internals my %stacks; -my @frames; +my @stack; +my %chunks; # trace id => { chunk_k => [stack] } while (defined(my $line = <>)) { + chomp $line; + + # if blank line, flush + if ($line eq '') { + $stacks{join(';', reverse @stack)} += 1 if @stack; + @stack = (); + next; + } + + # skip lines not beginning with a hash or a number next unless $line =~ /^(?:#|\d+) \S/; + # if this is part of a chunked trace (has trace_id metadata)... + if ($line =~ m{^# trace_id = (\d+)\.(\d+)(.)}) { + + # save stack to chunks hash + my ($id, $k, $m) = ($1, $2, $3); + $chunks{$id}{$k} = [@stack]; + @stack = (); + + # if this is the final chunk, flush + if ($m eq '!') { + my @chunk_keys = sort { $a <=> $b } keys %{$chunks{$id}}; + if (@chunk_keys == $k + 1 && $chunk_keys[-1] == $k) { + my @frames; + push @frames, @{$chunks{$id}{$_}} for @chunk_keys; + $stacks{join(';', reverse @frames)} += 1 if @frames; + } + delete $chunks{$id}; + } + next; + } + + # split line my ($depth, $func) = (split ' ', $line)[0,1]; - # decode the utf-8 bytes and make them into characters - # and turn anything that's invalid into U+FFFD - $func = decode("utf-8", $func); + # we only care about stack frames from here on + next if $depth eq '#'; - # Convert codepoints that break XML to ? + # strip chars that break xml + $func = decode("utf-8", $func); $func =~ s/[\x01-\x08\x0B-\x0C\x0E-\x1F\x7F-\x84\x86-\x9F]/\x3F/g; - - # turn it back into a string $func = encode("utf-8", $func); - if ($depth ne '#' && $depth == 0) { - $stacks{join(';', reverse @frames)} += 1 if @frames; - @frames = (); - } - - push @frames, $func if $line =~ /^\d/; + # push to stack + push @stack, $func; } -$stacks{join(';', reverse @frames)} += 1 if @frames; +$stacks{join(';', reverse @stack)} += 1 if @stack; while ( my ($k, $v) = each %stacks ) { print "$k $v\n"; diff --git a/tests/test_buffer_full.sh b/tests/test_buffer_full.sh index 5de9f0f..dee99eb 100755 --- a/tests/test_buffer_full.sh +++ b/tests/test_buffer_full.sh @@ -1,16 +1,37 @@ #!/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);') +# Nothing can fit in --buffer-size=1, so everything is truncated +test_phpspy_opts=(--buffer-size=1 --limit=10 -- "${PHP[@]}" -r 'usleep(1000000);') 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[b1_trunc]='^# truncated = 1$' +test_expected[b1_sentinel_bang]='^# trace_id = .*!$' +test_not_expected[b1_no_sentinel_tilde]='^# trace_id = .*~$' +test_not_expected[b1_no_frame]='^[0-9] ' test_invoke -test_phpspy_opts=(--buffer-size=24 -- "${PHP[@]}" -r 'usleep(1000000);') +# echo -n $'0 usleep :-1\n# trace_id = 0.0~\n\n' | wc -c # 42 +# Beyond 10 traces, we'd need 43 bytes for 2-digit trace_id +test_phpspy_opts=(--buffer-size=42 --limit=10 -- "${PHP[@]}" -r 'usleep(1000000);') +declare -A test_expected +declare -A test_not_expected +test_expected[b42_chunk1]='^# trace_id = 0\.0~$' +test_expected[b42_chunk2]='^# trace_id = 0\.1!$' +test_expected[b42_frame_0]='^0 usleep :-1$' +test_expected[b42_frame_1]='^1
:-1$' +test_not_expected[b42_no_trunc]='^# truncated = 1$' +test_invoke + +# 4k is ample space for non-chunked non-truncated +test_phpspy_opts=(--buffer-size=4096 --limit=10 -- "${PHP[@]}" -r 'usleep(1000000);') +declare -A test_expected declare -A test_not_expected -test_not_expected[anything]='^.+$' +test_expected[b4k_frame_0]='^0 usleep :-1$' +test_expected[b4k_frame_1]='^1
:-1$' +test_not_expected[b4k_no_trace]='^# trace_id =' +test_not_expected[b4k_no_trunc]='^# truncated = 1$' test_invoke diff --git a/tests/test_flamegraph.sh b/tests/test_flamegraph.sh index f90c8a4..2064437 100755 --- a/tests/test_flamegraph.sh +++ b/tests/test_flamegraph.sh @@ -1,29 +1,51 @@ #!/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" -_exit() { rm -f "$flame_svg"; } +repo=$(dirname "$(dirname "$TEST_SH")") -_run() { - local repo - flame_svg=$(mktemp) - repo=$(dirname "$(dirname "$TEST_SH")") - trap _exit EXIT +_exit() { test -z "${flame_tmp:-}" || rm -f "$flame_tmp"; } +trap _exit EXIT + +_flame() { + flame_tmp=$(mktemp) "$PHPSPY" -O/dev/null -E/dev/null --request-info=qcup 2>/dev/null \ -- "${PHP[@]}" -r 'sleep(2);' \ | "$repo/stackcollapse-phpspy.pl" \ | "$repo/vendor/flamegraph.pl" \ - > "$flame_svg" - test_assert_re "flamegraph_qcup" '\d+ samples' "$(cat "$flame_svg")" + > "$flame_tmp" + test_assert_re "flamegraph_qcup" '\d+ samples' "$(cat "$flame_tmp")" "$PHPSPY" -O/dev/null -E/dev/null --request-info=QCUP 2>/dev/null \ -- "${PHP[@]}" -r 'sleep(2);' \ | "$repo/stackcollapse-phpspy.pl" \ | "$repo/vendor/flamegraph.pl" \ - > "$flame_svg" - test_assert_re "flamegraph_QCUP" '\d+ samples' "$(cat "$flame_svg")" + > "$flame_tmp" + test_assert_re "flamegraph_QCUP" '\d+ samples' "$(cat "$flame_tmp")" + + "$PHPSPY" -O/dev/null -E/dev/null --buffer-size=128 2>/dev/null \ + -- "${PHP[@]}" -r '$f = fn($f, $n) => $n ? $f($f, $n - 1) : sleep(2); $f($f, 10);' \ + | "$repo/stackcollapse-phpspy.pl" \ + | "$repo/vendor/flamegraph.pl" \ + > "$flame_tmp" + test_assert_re "flamegraph_chunked" '\d+ samples' "$(cat "$flame_tmp")" + # all, main, 11 closures, sleep = 14 frames + test_assert "flamegraph_chunked_frames" 14 "$(grep -Pc '\d+ samples' <"$flame_tmp")" + + local fname + printf -v fname 'f%.0s' {1..200} + # everything after the truncated long fname should be dropped + "$PHPSPY" -O/dev/null -E/dev/null --buffer-size=128 2>/dev/null \ + -- "${PHP[@]}" -r "function $fname() { sleep(2); } function g() { $fname(); } g();" \ + | "$repo/stackcollapse-phpspy.pl" \ + > "$flame_tmp" + test_assert 'flamegraph_trunc_no_long_fname' 0 "$(grep -Fcwe "$fname" <"$flame_tmp")" + test_assert 'flamegraph_trunc_no_g' 0 "$(grep -Fcwe 'g' <"$flame_tmp")" + test_assert 'flamegraph_trunc_no_main' 0 "$(grep -Fcwe '
' <"$flame_tmp")" + test_assert 'flamegraph_trunc_yes_sleep' 0 "$(grep -Fqwe 'sleep' <"$flame_tmp"; echo $?)" } -test_fn=_run +test_fn=_flame test_invoke diff --git a/top.c b/top.c index 76859fd..a7ff32a 100644 --- a/top.c +++ b/top.c @@ -19,7 +19,7 @@ static void read_child_out(int fd); static void read_child_err(int fd); static void handle_line(char *line, int line_len); static void handle_event(struct tb_event *event); -static void display(); +static void display(void); static func_entry_t *func_map = NULL; static func_entry_t **func_list = NULL; @@ -283,7 +283,7 @@ static int func_list_compare(const void *a, const void *b) { return fb->count_excl > fa->count_excl ? 1 : -1; } -static void display() { +static void display(void) { int y, w, h; func_entry_t *el; size_t i;