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

[Andi Kleen <ak@linux.intel.com>]

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.


> +
> +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?


Rest looks good.

Reviewed-by: Andi Kleen <ak@linux.intel.com>


-Andi