From 65aee81afe7f6a54e2fb2de59e1d6cd47dcf8eb9 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Mon, 5 Sep 2022 10:34:23 +0300 Subject: perf intel-pt: Support itrace option flag d+e to log on error Pass d+e option and log size via intel_pt_log_enable(). Allocate a buffer for log messages and provide intel_pt_log_dump_buf() to dump and reset the buffer upon decoder errors. Example: $ sudo perf record -e intel_pt// sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.094 MB perf.data ] $ sudo perf config itrace.debug-log-buffer-size=300 $ sudo perf script --itrace=ed+e+o | head -20 Dumping debug log buffer (first line may be sliced) Other ffffffff96ca22f6: 48 89 e5 Other ffffffff96ca22f9: 65 48 8b 05 ff e0 38 69 Other ffffffff96ca2301: 48 3d c0 a5 c1 98 Other ffffffff96ca2307: 74 08 Jcc +8 ffffffff96ca2311: 5d Other ffffffff96ca2312: c3 Ret ERROR: Bad RET compression (TNT=N) at 0xffffffff96ca2312 End of debug log buffer dump instruction trace error type 1 time 15913.537143482 cpu 5 pid 36292 tid 36292 ip 0xffffffff96ca2312 code 6: Trace doesn't match instruction Dumping debug log buffer (first line may be sliced) Other ffffffff96ce7fe9: f6 47 2e 20 Other ffffffff96ce7fed: 74 11 Jcc +17 ffffffff96ce7fef: 48 8b 87 28 0a 00 00 Other ffffffff96ce7ff6: 5d Other ffffffff96ce7ff7: 48 8b 40 18 Other ffffffff96ce7ffb: c3 Ret ERROR: Bad RET compression (TNT=N) at 0xffffffff96ce7ffb Warning: 8 instruction trace errors Reviewed-by: Andi Kleen Reviewed-by: Namhyung Kim Signed-off-by: Adrian Hunter Cc: Ian Rogers Cc: Jiri Olsa Link: https://lore.kernel.org/r/20220905073424.3971-6-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/intel-pt-decoder/intel-pt-log.c | 94 ++++++++++++++++++++++++- 1 file changed, 93 insertions(+), 1 deletion(-) (limited to 'tools/perf/util/intel-pt-decoder/intel-pt-log.c') diff --git a/tools/perf/util/intel-pt-decoder/intel-pt-log.c b/tools/perf/util/intel-pt-decoder/intel-pt-log.c index 5f5dfc8753f3..24684edc49f7 100644 --- a/tools/perf/util/intel-pt-decoder/intel-pt-log.c +++ b/tools/perf/util/intel-pt-decoder/intel-pt-log.c @@ -5,12 +5,16 @@ */ #include +#include #include #include #include #include #include +#include +#include + #include "intel-pt-log.h" #include "intel-pt-insn-decoder.h" @@ -18,18 +22,33 @@ #define MAX_LOG_NAME 256 +#define DFLT_BUF_SZ (16 * 1024) + +struct log_buf { + char *buf; + size_t buf_sz; + size_t head; + bool wrapped; + FILE *backend; +}; + static FILE *f; static char log_name[MAX_LOG_NAME]; bool intel_pt_enable_logging; +static bool intel_pt_dump_log_on_error; +static unsigned int intel_pt_log_on_error_size; +static struct log_buf log_buf; void *intel_pt_log_fp(void) { return f; } -void intel_pt_log_enable(void) +void intel_pt_log_enable(bool dump_log_on_error, unsigned int log_on_error_size) { intel_pt_enable_logging = true; + intel_pt_dump_log_on_error = dump_log_on_error; + intel_pt_log_on_error_size = log_on_error_size; } void intel_pt_log_disable(void) @@ -74,6 +93,77 @@ static void intel_pt_print_no_data(uint64_t pos, int indent) fprintf(f, " "); } +static ssize_t log_buf__write(void *cookie, const char *buf, size_t size) +{ + struct log_buf *b = cookie; + size_t sz = size; + + if (!b->buf) + return size; + + while (sz) { + size_t space = b->buf_sz - b->head; + size_t n = min(space, sz); + + memcpy(b->buf + b->head, buf, n); + sz -= n; + buf += n; + b->head += n; + if (sz && b->head >= b->buf_sz) { + b->head = 0; + b->wrapped = true; + } + } + return size; +} + +static int log_buf__close(void *cookie) +{ + struct log_buf *b = cookie; + + zfree(&b->buf); + return 0; +} + +static FILE *log_buf__open(struct log_buf *b, FILE *backend, unsigned int sz) +{ + cookie_io_functions_t fns = { + .write = log_buf__write, + .close = log_buf__close, + }; + FILE *file; + + memset(b, 0, sizeof(*b)); + b->buf_sz = sz; + b->buf = malloc(b->buf_sz); + b->backend = backend; + file = fopencookie(b, "a", fns); + if (!file) + zfree(&b->buf); + return file; +} + +static void log_buf__dump(struct log_buf *b) +{ + if (!b->buf) + return; + + fflush(f); + fprintf(b->backend, "Dumping debug log buffer (first line may be sliced)\n"); + if (b->wrapped) + fwrite(b->buf + b->head, b->buf_sz - b->head, 1, b->backend); + fwrite(b->buf, b->head, 1, b->backend); + fprintf(b->backend, "End of debug log buffer dump\n"); + + b->head = 0; + b->wrapped = false; +} + +void intel_pt_log_dump_buf(void) +{ + log_buf__dump(&log_buf); +} + static int intel_pt_log_open(void) { if (!intel_pt_enable_logging) @@ -86,6 +176,8 @@ static int intel_pt_log_open(void) f = fopen(log_name, "w+"); else f = stdout; + if (f && intel_pt_dump_log_on_error) + f = log_buf__open(&log_buf, f, intel_pt_log_on_error_size); if (!f) { intel_pt_enable_logging = false; return -1; -- cgit v1.2.3 From 3b7ae354c1fcb783848b46e1c1140a66ba742672 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Mon, 5 Sep 2022 10:34:24 +0300 Subject: perf intel-pt: Remove first line of log dumped on error Instead of printing "(first line may be sliced)", always remove the first line of the debug log if the buffer has wrapped when dumping on error. Signed-off-by: Adrian Hunter Reviewed-by: Namhyung Kim Cc: Andi Kleen Cc: Ian Rogers Cc: Jiri Olsa Link: https://lore.kernel.org/r/20220905073424.3971-7-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/intel-pt-decoder/intel-pt-log.c | 33 +++++++++++++++++++++---- 1 file changed, 28 insertions(+), 5 deletions(-) (limited to 'tools/perf/util/intel-pt-decoder/intel-pt-log.c') diff --git a/tools/perf/util/intel-pt-decoder/intel-pt-log.c b/tools/perf/util/intel-pt-decoder/intel-pt-log.c index 24684edc49f7..ef55d6232cf0 100644 --- a/tools/perf/util/intel-pt-decoder/intel-pt-log.c +++ b/tools/perf/util/intel-pt-decoder/intel-pt-log.c @@ -143,16 +143,39 @@ static FILE *log_buf__open(struct log_buf *b, FILE *backend, unsigned int sz) return file; } +static bool remove_first_line(const char **p, size_t *n) +{ + for (; *n && **p != '\n'; ++*p, --*n) + ; + if (*n) { + *p += 1; + *n -= 1; + return true; + } + return false; +} + +static void write_lines(const char *p, size_t n, FILE *fp, bool *remove_first) +{ + if (*remove_first) + *remove_first = !remove_first_line(&p, &n); + fwrite(p, n, 1, fp); +} + static void log_buf__dump(struct log_buf *b) { + bool remove_first = false; + if (!b->buf) return; - fflush(f); - fprintf(b->backend, "Dumping debug log buffer (first line may be sliced)\n"); - if (b->wrapped) - fwrite(b->buf + b->head, b->buf_sz - b->head, 1, b->backend); - fwrite(b->buf, b->head, 1, b->backend); + fflush(f); /* Could update b->head and b->wrapped */ + fprintf(b->backend, "Dumping debug log buffer\n"); + if (b->wrapped) { + remove_first = true; + write_lines(b->buf + b->head, b->buf_sz - b->head, b->backend, &remove_first); + } + write_lines(b->buf, b->head, b->backend, &remove_first); fprintf(b->backend, "End of debug log buffer dump\n"); b->head = 0; -- cgit v1.2.3