Re: [PATCH 5/5] perf intel-pt: Support itrace option flag d+e to log on error

From: Adrian Hunter
Date: Thu Sep 01 2022 - 12:29:07 EST


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@xxxxxxxxx>
>> ---
>>   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@xxxxxxxxx>
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@xxxxxxxxx>
---
.../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