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;
+		}
+	}
+	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;
diff --git a/tools/perf/util/intel-pt-decoder/intel-pt-log.h b/tools/perf/util/intel-pt-decoder/intel-pt-log.h
index d900aab24b21..354d7d23fc81 100644
--- a/tools/perf/util/intel-pt-decoder/intel-pt-log.h
+++ b/tools/perf/util/intel-pt-decoder/intel-pt-log.h
@@ -14,9 +14,10 @@
 struct intel_pt_pkt;
 
 void *intel_pt_log_fp(void);
-void intel_pt_log_enable(void);
+void intel_pt_log_enable(bool dump_log_on_error, unsigned int log_on_error_size);
 void intel_pt_log_disable(void);
 void intel_pt_log_set_name(const char *name);
+void intel_pt_log_dump_buf(void);
 
 void __intel_pt_log_packet(const struct intel_pt_pkt *packet, int pkt_len,
 			   uint64_t pos, const unsigned char *buf);
diff --git a/tools/perf/util/intel-pt.c b/tools/perf/util/intel-pt.c
index c01ff8001501..b34cb3dec1aa 100644
--- a/tools/perf/util/intel-pt.c
+++ b/tools/perf/util/intel-pt.c
@@ -2419,6 +2419,8 @@ static int intel_pt_synth_error(struct intel_pt *pt, int code, int cpu,
 				pid_t pid, pid_t tid, u64 ip, u64 timestamp,
 				pid_t machine_pid, int vcpu)
 {
+	bool dump_log_on_error = pt->synth_opts.log_plus_flags & AUXTRACE_LOG_FLG_ON_ERROR;
+	bool log_on_stdout = pt->synth_opts.log_plus_flags & AUXTRACE_LOG_FLG_USE_STDOUT;
 	union perf_event event;
 	char msg[MAX_AUXTRACE_ERROR_MSG];
 	int err;
@@ -2438,6 +2440,16 @@ static int intel_pt_synth_error(struct intel_pt *pt, int code, int cpu,
 				   code, cpu, pid, tid, ip, msg, timestamp,
 				   machine_pid, vcpu);
 
+	if (intel_pt_enable_logging && !log_on_stdout) {
+		FILE *fp = intel_pt_log_fp();
+
+		if (fp)
+			perf_event__fprintf_auxtrace_error(&event, fp);
+	}
+
+	if (code != INTEL_PT_ERR_LOST && dump_log_on_error)
+		intel_pt_log_dump_buf();
+
 	err = perf_session__deliver_synth_event(pt->session, &event, NULL);
 	if (err)
 		pr_err("Intel Processor Trace: failed to deliver error event, error %d\n",
@@ -4272,8 +4284,12 @@ int intel_pt_process_auxtrace_info(union perf_event *event,
 		goto err_delete_thread;
 	}
 
-	if (pt->synth_opts.log)
-		intel_pt_log_enable();
+	if (pt->synth_opts.log) {
+		bool log_on_error = pt->synth_opts.log_plus_flags & AUXTRACE_LOG_FLG_ON_ERROR;
+		unsigned int log_on_error_size = pt->synth_opts.log_on_error_size;
+
+		intel_pt_log_enable(log_on_error, log_on_error_size);
+	}
 
 	/* Maximum non-turbo ratio is TSC freq / 100 MHz */
 	if (pt->tc.time_mult) {
-- 
2.25.1

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

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

On Thu, Sep 1, 2022 at 9:29 AM Adrian Hunter <adrian.hunter@intel.com> wrote:
>
> On 1/09/22 17:31, Andi Kleen wrote:
> >
> > On 9/1/2022 4:00 AM, Adrian Hunter wrote:

[SNIP]
> >> +
> >> +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;

Isn't it only required when the buf is wrapped?

Thanks,
Namhyung


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

On 2/09/22 04:34, Namhyung Kim wrote:
> On Thu, Sep 1, 2022 at 9:29 AM Adrian Hunter <adrian.hunter@intel.com> wrote:
>>
>> On 1/09/22 17:31, Andi Kleen wrote:
>>>
>>> On 9/1/2022 4:00 AM, Adrian Hunter wrote:
> 
> [SNIP]
>>>> +
>>>> +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;
> 
> Isn't it only required when the buf is wrapped?

Very true! Thanks for spotting that!

I will send a new version.

> 
> Thanks,
> Namhyung
> 
> 
>> +
>>         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
>>

Em Fri, Sep 02, 2022 at 03:01:01PM +0300, Adrian Hunter escreveu:
> On 2/09/22 04:34, Namhyung Kim wrote:
> > On Thu, Sep 1, 2022 at 9:29 AM Adrian Hunter <adrian.hunter@intel.com> wrote:
> >>
> >> On 1/09/22 17:31, Andi Kleen wrote:
> >>>
> >>> On 9/1/2022 4:00 AM, Adrian Hunter wrote:
> > 
> > [SNIP]
> >>>> +
> >>>> +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;
> > 
> > Isn't it only required when the buf is wrapped?
> 
> Very true! Thanks for spotting that!
> 
> I will send a new version.

Ok, I'll remove the one I've been testing, please fix the problems below, found with several compilers/distros:

The 'struct log_buf' definition is coming after its usage on a static variable,
please move the variable to after the definition.

  80    56.88 ubuntu:22.10                  : FAIL gcc version 11.3.0 (Ubuntu 11.3.0-5ubuntu1) 
    util/intel-pt-decoder/intel-pt-log.c:30:23: error: tentative definition of variable with internal linkage has incomplete non-array type 'struct log_buf' [-Werror,-Wtentative-definition-incomplete-type]
    static struct log_buf log_buf;
                          ^
    util/intel-pt-decoder/intel-pt-log.c:30:15: note: forward declaration of 'struct log_buf'
    static struct log_buf log_buf;
                  ^
    1 error generated.
    error: unknown warning option '-Wno-format-overflow'; did you mean '-Wno-shift-overflow'? [-Werror,-Wunknown-warning-option]
    make[4]: *** [/git/perf-6.0.0-rc3/tools/build/Makefile.build:139: intel-pt-decoder] Error 2
    make[3]: *** [/git/perf-6.0.0-rc3/tools/build/Makefile.build:139: util] Error 2


This one also appeared in some builds, just as a warning:

dlfilters/dlfilter-show-cycles.c: In function 'print_vals':
dlfilters/dlfilter-show-cycles.c:101:16: warning: format '%llu' expects argument of type 'long long unsigned int', but argument 2 has type '__u64' {aka 'long unsigned int'} [-Wformat=]
  101 |   printf("%10llu %10llu ", cycles, delta);
      |           ~~~~~^           ~~~~~~
      |                |           |
      |                |           __u64 {aka long unsigned int}
      |                long long unsigned int
      |           %10lu
dlfilters/dlfilter-show-cycles.c:101:23: warning: format '%llu' expects argument of type 'long long unsigned int', but argument 3 has type '__u64' {aka 'long unsigned int'} [-Wformat=]
  101 |   printf("%10llu %10llu ", cycles, delta);
      |                  ~~~~~^            ~~~~~
      |                       |            |
      |                       |            __u64 {aka long unsigned int}
      |                       long long unsigned int
      |                  %10lu
dlfilters/dlfilter-show-cycles.c:103:16: warning: format '%llu' expects argument of type 'long long unsigned int', but argument 2 has type '__u64' {aka 'long unsigned int'} [-Wformat=]
  103 |   printf("%10llu %10s ", cycles, "");
      |           ~~~~~^         ~~~~~~
      |                |         |
      |                |         __u64 {aka long unsigned int}
      |                long long unsigned int
      |           %10lu