Messages in this thread Patch in this message | | | Date | Thu, 1 Sep 2022 19:28:49 +0300 | Subject | Re: [PATCH 5/5] perf intel-pt: Support itrace option flag d+e to log on error | From | Adrian Hunter <> |
| |
On 1/09/22 17:31, Andi Kleen wrote: > > On 9/1/2022 4:00 AM, Adrian Hunter wrote: >> 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 >> >> Signed-off-by: Adrian Hunter <adrian.hunter@intel.com> >> --- >> tools/perf/Documentation/perf-intel-pt.txt | 5 +- >> .../perf/util/intel-pt-decoder/intel-pt-log.c | 94 ++++++++++++++++++- >> .../perf/util/intel-pt-decoder/intel-pt-log.h | 3 +- >> tools/perf/util/intel-pt.c | 20 +++- >> 4 files changed, 117 insertions(+), 5 deletions(-) >> >> diff --git a/tools/perf/Documentation/perf-intel-pt.txt b/tools/perf/Documentation/perf-intel-pt.txt >> index d5ddb968bcf4..92464a5d7eaf 100644 >> --- a/tools/perf/Documentation/perf-intel-pt.txt >> +++ b/tools/perf/Documentation/perf-intel-pt.txt >> @@ -989,10 +989,13 @@ must be preceded by either '+' or '-'. The flags support by Intel PT are: >> -a Suppress logging of perf events >> +a Log all perf events >> + +e Output only on decoding errors (size configurable) >> +o Output to stdout instead of "intel_pt.log" >> By default, logged perf events are filtered by any specified time ranges, but >> -flag +a overrides that. >> +flag +a overrides that. The +e flag can be useful for analyzing errors. By >> +default, the log size in that case is 16384 bytes, but can be altered by >> +linkperf:perf-config[1] e.g. perf config itrace.debug-log-buffer-size=30000 >> In addition, the period of the "instructions" event can be specified. e.g. >> 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..ea96dcae187a 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 <stdio.h> >> +#include <stdlib.h> >> #include <stdint.h> >> #include <inttypes.h> >> #include <stdarg.h> >> #include <stdbool.h> >> #include <string.h> >> +#include <linux/zalloc.h> >> +#include <linux/kernel.h> >> + >> #include "intel-pt-log.h" >> #include "intel-pt-insn-decoder.h" >> @@ -21,15 +25,20 @@ >> 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 +83,87 @@ static void intel_pt_print_no_data(uint64_t pos, int indent) >> fprintf(f, " "); >> } >> +#define DFLT_BUF_SZ (16 * 1024) >> + >> +struct log_buf { >> + char *buf; >> + size_t buf_sz; >> + size_t head; >> + bool wrapped; >> + FILE *backend; >> +}; >> + >> +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; >> + } >> + } > > > I would add an assert or somesuch for the case where sz is larger than the buffer size, which would otherwise loop forever.
It will just overwrite itself a few times, as b->head keeps wrapping back to 0.
> > >> + >> +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"); > > > Should be easy to skip the first line, no?
Not as easy as typing " (first line may be sliced)" ;-)
Still not sure it is worth having the extra complication, but here is the change as a separate patch:
From: Adrian Hunter <adrian.hunter@intel.com> Date: Thu, 1 Sep 2022 19:01:33 +0300 Subject: [PATCH] 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 when dumping on error.
Signed-off-by: Adrian Hunter <adrian.hunter@intel.com> --- .../perf/util/intel-pt-decoder/intel-pt-log.c | 27 ++++++++++++++++--- 1 file changed, 24 insertions(+), 3 deletions(-)
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 ea96dcae187a7..6cc465d1f7a9e 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,37 @@ 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 = true; + if (!b->buf) return; fflush(f); - fprintf(b->backend, "Dumping debug log buffer (first line may be sliced)\n"); + fprintf(b->backend, "Dumping debug log buffer\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); + 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; -- 2.34.1
| |