Hi
Here are a few patches to add the ability to output the decoding debug log
only when there are decoding errors.
This is motivated by the fact that a full log can be very large, so just
getting interesting bits is useful for analyzing errors.
If necessary, the size of output on error is configurable via perf config,
and perf_config_scan() was added in the 1st patch to make that simpler.
The 2nd patch adds the new option flag to auxtrace.
There are a couple of very minor and essentially unrelated changes in
patches 3 and 4.
The main Intel PT change is in patch 5 and there is a small example in the
commit message.
Adrian Hunter (5):
perf tools: Add perf_config_scan()
perf auxtrace: Add itrace option flag d+e to log on error
perf intel-pt: Improve man page layout slightly
perf intel-pt: Improve object code read error message
perf intel-pt: Support itrace option flag d+e to log on error
tools/perf/Documentation/itrace.txt | 1 +
tools/perf/Documentation/perf-config.txt | 7 ++
tools/perf/Documentation/perf-intel-pt.txt | 13 +++-
tools/perf/util/auxtrace.c | 13 ++++
tools/perf/util/auxtrace.h | 3 +
tools/perf/util/config.c | 31 ++++++++
tools/perf/util/config.h | 1 +
tools/perf/util/intel-pt-decoder/intel-pt-log.c | 94 ++++++++++++++++++++++++-
tools/perf/util/intel-pt-decoder/intel-pt-log.h | 3 +-
tools/perf/util/intel-pt.c | 23 +++++-
10 files changed, 183 insertions(+), 6 deletions(-)
Regards
Adrian
Add flag +e to the itrace d (decoder debug log) option to get output only
on decoding errors.
The log can be very big so reducing the output to where there are decoding
errors can be useful for analyzing errors.
By default, the log size in that case is 16384 bytes, but can be altered by
perf config e.g. perf config itrace.debug-log-buffer-size=30000
Signed-off-by: Adrian Hunter <[email protected]>
---
tools/perf/Documentation/itrace.txt | 1 +
tools/perf/Documentation/perf-config.txt | 7 +++++++
tools/perf/util/auxtrace.c | 13 +++++++++++++
tools/perf/util/auxtrace.h | 3 +++
4 files changed, 24 insertions(+)
diff --git a/tools/perf/Documentation/itrace.txt b/tools/perf/Documentation/itrace.txt
index 6b189669c450..0916bbfe64cb 100644
--- a/tools/perf/Documentation/itrace.txt
+++ b/tools/perf/Documentation/itrace.txt
@@ -64,6 +64,7 @@
debug messages will or will not be logged. Each flag must be preceded
by either '+' or '-'. The flags are:
a all perf events
+ e output only on errors (size configurable - see linkperf:perf-config[1])
o output to stdout
If supported, the 'q' option may be repeated to increase the effect.
diff --git a/tools/perf/Documentation/perf-config.txt b/tools/perf/Documentation/perf-config.txt
index 0420e71698ee..39c890ead2dc 100644
--- a/tools/perf/Documentation/perf-config.txt
+++ b/tools/perf/Documentation/perf-config.txt
@@ -729,6 +729,13 @@ auxtrace.*::
If the directory does not exist or has the wrong file type,
the current directory is used.
+itrace.*::
+
+ debug-log-buffer-size::
+ Log size in bytes to output when using the option --itrace=d+e
+ Refer 'itrace' option of linkperf:perf-script[1] or
+ linkperf:perf-report[1]. The default is 16384.
+
daemon.*::
daemon.base::
diff --git a/tools/perf/util/auxtrace.c b/tools/perf/util/auxtrace.c
index 6edab8a16de6..b59c278fe9ed 100644
--- a/tools/perf/util/auxtrace.c
+++ b/tools/perf/util/auxtrace.c
@@ -26,6 +26,7 @@
#include <linux/list.h>
#include <linux/zalloc.h>
+#include "config.h"
#include "evlist.h"
#include "dso.h"
#include "map.h"
@@ -1434,6 +1435,16 @@ static int get_flags(const char **ptr, unsigned int *plus_flags, unsigned int *m
}
}
+#define ITRACE_DFLT_LOG_ON_ERROR_SZ 16384
+
+static unsigned int itrace_log_on_error_size(void)
+{
+ unsigned int sz = 0;
+
+ perf_config_scan("itrace.debug-log-buffer-size", "%u", &sz);
+ return sz ?: ITRACE_DFLT_LOG_ON_ERROR_SZ;
+}
+
/*
* Please check tools/perf/Documentation/perf-script.txt for information
* about the options parsed here, which is introduced after this cset,
@@ -1532,6 +1543,8 @@ int itrace_do_parse_synth_opts(struct itrace_synth_opts *synth_opts,
if (get_flags(&p, &synth_opts->log_plus_flags,
&synth_opts->log_minus_flags))
goto out_err;
+ if (synth_opts->log_plus_flags & AUXTRACE_LOG_FLG_ON_ERROR)
+ synth_opts->log_on_error_size = itrace_log_on_error_size();
break;
case 'c':
synth_opts->branches = true;
diff --git a/tools/perf/util/auxtrace.h b/tools/perf/util/auxtrace.h
index 6a4fbfd34c6b..cb8e0a01abb6 100644
--- a/tools/perf/util/auxtrace.h
+++ b/tools/perf/util/auxtrace.h
@@ -60,6 +60,7 @@ enum itrace_period_type {
#define AUXTRACE_ERR_FLG_DATA_LOST (1 << ('l' - 'a'))
#define AUXTRACE_LOG_FLG_ALL_PERF_EVTS (1 << ('a' - 'a'))
+#define AUXTRACE_LOG_FLG_ON_ERROR (1 << ('e' - 'a'))
#define AUXTRACE_LOG_FLG_USE_STDOUT (1 << ('o' - 'a'))
/**
@@ -110,6 +111,7 @@ enum itrace_period_type {
* @log_plus_flags: flags to affect what is logged
* @log_minus_flags: flags to affect what is logged
* @quick: quicker (less detailed) decoding
+ * @log_on_error_size: size of log to keep for outputting log only on errors
*/
struct itrace_synth_opts {
bool set;
@@ -155,6 +157,7 @@ struct itrace_synth_opts {
unsigned int log_plus_flags;
unsigned int log_minus_flags;
unsigned int quick;
+ unsigned int log_on_error_size;
};
/**
--
2.25.1
Improve man page layout slightly by adding blank lines.
Signed-off-by: Adrian Hunter <[email protected]>
---
tools/perf/Documentation/perf-intel-pt.txt | 8 ++++++++
1 file changed, 8 insertions(+)
diff --git a/tools/perf/Documentation/perf-intel-pt.txt b/tools/perf/Documentation/perf-intel-pt.txt
index 3dc3f0ccbd51..d5ddb968bcf4 100644
--- a/tools/perf/Documentation/perf-intel-pt.txt
+++ b/tools/perf/Documentation/perf-intel-pt.txt
@@ -943,12 +943,15 @@ event packets are recorded only if the "pwr_evt" config term was used. Refer to
the config terms section above. The power events record information about
C-state changes, whereas CBR is indicative of CPU frequency. perf script
"event,synth" fields display information like this:
+
cbr: cbr: 22 freq: 2189 MHz (200%)
mwait: hints: 0x60 extensions: 0x1
pwre: hw: 0 cstate: 2 sub-cstate: 0
exstop: ip: 1
pwrx: deepest cstate: 2 last cstate: 2 wake reason: 0x4
+
Where:
+
"cbr" includes the frequency and the percentage of maximum non-turbo
"mwait" shows mwait hints and extensions
"pwre" shows C-state transitions (to a C-state deeper than C0) and
@@ -956,6 +959,7 @@ Where:
"exstop" indicates execution stopped and whether the IP was recorded
exactly,
"pwrx" indicates return to C0
+
For more details refer to the Intel 64 and IA-32 Architectures Software
Developer Manuals.
@@ -969,8 +973,10 @@ are quite important. Users must know if what they are seeing is a complete
picture or not. The "e" option may be followed by flags which affect what errors
will or will not be reported. Each flag must be preceded by either '+' or '-'.
The flags supported by Intel PT are:
+
-o Suppress overflow errors
-l Suppress trace data lost errors
+
For example, for errors but not overflow or data lost errors:
--itrace=e-o-l
@@ -980,9 +986,11 @@ decoded packets and instructions. Note that this option slows down the decoder
and that the resulting file may be very large. The "d" option may be followed
by flags which affect what debug messages will or will not be logged. Each flag
must be preceded by either '+' or '-'. The flags support by Intel PT are:
+
-a Suppress logging of perf events
+a Log all perf events
+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.
--
2.25.1
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 <[email protected]>
---
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
To simplify getting a single config value, add a function to scan a config
variable.
Signed-off-by: Adrian Hunter <[email protected]>
---
tools/perf/util/config.c | 31 +++++++++++++++++++++++++++++++
tools/perf/util/config.h | 1 +
2 files changed, 32 insertions(+)
diff --git a/tools/perf/util/config.c b/tools/perf/util/config.c
index 60ce5908c664..3f2ae19a1dd4 100644
--- a/tools/perf/util/config.c
+++ b/tools/perf/util/config.c
@@ -908,3 +908,34 @@ void set_buildid_dir(const char *dir)
/* for communicating with external commands */
setenv("PERF_BUILDID_DIR", buildid_dir, 1);
}
+
+struct perf_config_scan_data {
+ const char *name;
+ const char *fmt;
+ va_list args;
+ int ret;
+};
+
+static int perf_config_scan_cb(const char *var, const char *value, void *data)
+{
+ struct perf_config_scan_data *d = data;
+
+ if (!strcmp(var, d->name))
+ d->ret = vsscanf(value, d->fmt, d->args);
+
+ return 0;
+}
+
+int perf_config_scan(const char *name, const char *fmt, ...)
+{
+ struct perf_config_scan_data d = {
+ .name = name,
+ .fmt = fmt,
+ };
+
+ va_start(d.args, fmt);
+ perf_config(perf_config_scan_cb, &d);
+ va_end(d.args);
+
+ return d.ret;
+}
diff --git a/tools/perf/util/config.h b/tools/perf/util/config.h
index 2fd77aaff4d2..2e5e808928a5 100644
--- a/tools/perf/util/config.h
+++ b/tools/perf/util/config.h
@@ -29,6 +29,7 @@ typedef int (*config_fn_t)(const char *, const char *, void *);
int perf_default_config(const char *, const char *, void *);
int perf_config(config_fn_t fn, void *);
+int perf_config_scan(const char *name, const char *fmt, ...) __scanf(2, 3);
int perf_config_set(struct perf_config_set *set,
config_fn_t fn, void *data);
int perf_config_int(int *dest, const char *, const char *);
--
2.25.1
The offset is more readable in hex instead of decimal.
Signed-off-by: Adrian Hunter <[email protected]>
---
tools/perf/util/intel-pt.c | 3 ++-
1 file changed, 2 insertions(+), 1 deletion(-)
diff --git a/tools/perf/util/intel-pt.c b/tools/perf/util/intel-pt.c
index d5e9fc8106dd..c01ff8001501 100644
--- a/tools/perf/util/intel-pt.c
+++ b/tools/perf/util/intel-pt.c
@@ -842,7 +842,8 @@ static int intel_pt_walk_next_insn(struct intel_pt_insn *intel_pt_insn,
offset, buf,
INTEL_PT_INSN_BUF_SZ);
if (len <= 0) {
- intel_pt_log("ERROR: failed to read at %" PRIu64 " ", offset);
+ intel_pt_log("ERROR: failed to read at offset %#" PRIx64 " ",
+ offset);
if (intel_pt_enable_logging)
dso__fprintf(al.map->dso, intel_pt_log_fp());
return -EINVAL;
--
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 <[email protected]>
> ---
> 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 <[email protected]>
-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 <[email protected]>
>> ---
>> 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 <[email protected]>
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 <[email protected]>
---
.../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 <[email protected]> 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 <[email protected]>
> 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 <[email protected]>
> ---
> .../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 <[email protected]> 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 <[email protected]>
>> 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 <[email protected]>
>> ---
>> .../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 <[email protected]> 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 <[email protected]>
> >> 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 <[email protected]>
> >> ---
> >> .../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