From 4c95ad261cfac120dd66238fcae222766754c219 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Tue, 30 Jun 2020 16:39:35 +0300 Subject: perf intel-pt: Fix PEBS sample for XMM registers The condition to add XMM registers was missing, the regs array needed to be in the outer scope, and the size of the regs array was too small. Fixes: 143d34a6b387b ("perf intel-pt: Add XMM registers to synthesized PEBS sample") Signed-off-by: Adrian Hunter Cc: Jiri Olsa Cc: Luwei Kang Link: http://lore.kernel.org/lkml/20200630133935.11150-4-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/intel-pt.c | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) (limited to 'tools/perf/util/intel-pt.c') diff --git a/tools/perf/util/intel-pt.c b/tools/perf/util/intel-pt.c index e4dd8bf610ce..cb3c1e569a2d 100644 --- a/tools/perf/util/intel-pt.c +++ b/tools/perf/util/intel-pt.c @@ -1735,6 +1735,7 @@ static int intel_pt_synth_pebs_sample(struct intel_pt_queue *ptq) u64 sample_type = evsel->core.attr.sample_type; u64 id = evsel->core.id[0]; u8 cpumode; + u64 regs[8 * sizeof(sample.intr_regs.mask)]; if (intel_pt_skip_event(pt)) return 0; @@ -1784,8 +1785,8 @@ static int intel_pt_synth_pebs_sample(struct intel_pt_queue *ptq) } if (sample_type & PERF_SAMPLE_REGS_INTR && - items->mask[INTEL_PT_GP_REGS_POS]) { - u64 regs[sizeof(sample.intr_regs.mask)]; + (items->mask[INTEL_PT_GP_REGS_POS] || + items->mask[INTEL_PT_XMM_POS])) { u64 regs_mask = evsel->core.attr.sample_regs_intr; u64 *pos; -- cgit v1.2.3 From b22f90aaea4bbf09a5ad75c215ce0a01227e2a00 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Tue, 12 May 2020 15:19:20 +0300 Subject: perf intel-pt: Add support for text poke events Select text poke events when available and the kernel is being traced. Process text poke events to invalidate entries in Intel PT's instruction cache. Example: The example requires kernel config: CONFIG_PROC_SYSCTL=y CONFIG_SCHED_DEBUG=y CONFIG_SCHEDSTATS=y Before: # perf record -o perf.data.before --kcore -a -e intel_pt//k -m,64M & # cat /proc/sys/kernel/sched_schedstats 0 # echo 1 > /proc/sys/kernel/sched_schedstats # cat /proc/sys/kernel/sched_schedstats 1 # echo 0 > /proc/sys/kernel/sched_schedstats # cat /proc/sys/kernel/sched_schedstats 0 # kill %1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 3.341 MB perf.data.before ] [1]+ Terminated perf record -o perf.data.before --kcore -a -e intel_pt//k -m,64M # perf script -i perf.data.before --itrace=e >/dev/null Warning: 474 instruction trace errors After: # perf record -o perf.data.after --kcore -a -e intel_pt//k -m,64M & # cat /proc/sys/kernel/sched_schedstats 0 # echo 1 > /proc/sys/kernel/sched_schedstats # cat /proc/sys/kernel/sched_schedstats 1 # echo 0 > /proc/sys/kernel/sched_schedstats # cat /proc/sys/kernel/sched_schedstats 0 # kill %1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 2.646 MB perf.data.after ] [1]+ Terminated perf record -o perf.data.after --kcore -a -e intel_pt//k -m,64M # perf script -i perf.data.after --itrace=e >/dev/null Example: The example requires kernel config: # CONFIG_FUNCTION_TRACER is not set Before: # perf record --kcore -m,64M -o t1 -a -e intel_pt//k & # perf probe __schedule Added new event: probe:__schedule (on __schedule) You can now use it in all perf tools, such as: perf record -e probe:__schedule -aR sleep 1 # perf record -e probe:__schedule -aR sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.026 MB perf.data (68 samples) ] # perf probe -d probe:__schedule Removed event: probe:__schedule # kill %1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 41.268 MB t1 ] [1]+ Terminated perf record --kcore -m,64M -o t1 -a -e intel_pt//k # perf script -i t1 --itrace=e >/dev/null Warning: 207 instruction trace errors After: # perf record --kcore -m,64M -o t1 -a -e intel_pt//k & # perf probe __schedule Added new event: probe:__schedule (on __schedule) You can now use it in all perf tools, such as: perf record -e probe:__schedule -aR sleep 1 # perf record -e probe:__schedule -aR sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.028 MB perf.data (107 samples) ] # perf probe -d probe:__schedule Removed event: probe:__schedule # kill %1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 39.978 MB t1 ] [1]+ Terminated perf record --kcore -m,64M -o t1 -a -e intel_pt//k # perf script -i t1 --itrace=e >/dev/null # perf script -i t1 --no-itrace -D | grep 'POKE\|KSYMBOL' 6 565303693547 0x291f18 [0x50]: PERF_RECORD_KSYMBOL addr ffffffffc027a000 len 4096 type 2 flags 0x0 name kprobe_insn_page 6 565303697010 0x291f68 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffc027a000 old len 0 new len 6 6 565303838278 0x291fa8 [0x50]: PERF_RECORD_KSYMBOL addr ffffffffc027c000 len 4096 type 2 flags 0x0 name kprobe_optinsn_page 6 565303848286 0x291ff8 [0xa0]: PERF_RECORD_TEXT_POKE addr 0xffffffffc027c000 old len 0 new len 106 6 565369336743 0x292af8 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffff88ab8890 old len 5 new len 5 7 566434327704 0x217c208 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffff88ab8890 old len 5 new len 5 6 566456313475 0x293198 [0xa0]: PERF_RECORD_TEXT_POKE addr 0xffffffffc027c000 old len 106 new len 0 6 566456314935 0x293238 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffc027a000 old len 6 new len 0 Example: The example requires kernel config: CONFIG_FUNCTION_TRACER=y Before: # perf record --kcore -m,64M -o t1 -a -e intel_pt//k & # perf probe __kmalloc Added new event: probe:__kmalloc (on __kmalloc) You can now use it in all perf tools, such as: perf record -e probe:__kmalloc -aR sleep 1 # perf record -e probe:__kmalloc -aR sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.022 MB perf.data (6 samples) ] # perf probe -d probe:__kmalloc Removed event: probe:__kmalloc # kill %1 [ perf record: Woken up 2 times to write data ] [ perf record: Captured and wrote 43.850 MB t1 ] [1]+ Terminated perf record --kcore -m,64M -o t1 -a -e intel_pt//k # perf script -i t1 --itrace=e >/dev/null Warning: 8 instruction trace errors After: # perf record --kcore -m,64M -o t1 -a -e intel_pt//k & # perf probe __kmalloc Added new event: probe:__kmalloc (on __kmalloc) You can now use it in all perf tools, such as: perf record -e probe:__kmalloc -aR sleep 1 # perf record -e probe:__kmalloc -aR sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.037 MB perf.data (206 samples) ] # perf probe -d probe:__kmalloc Removed event: probe:__kmalloc # kill %1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 41.442 MB t1 ] [1]+ Terminated perf record --kcore -m,64M -o t1 -a -e intel_pt//k # perf script -i t1 --itrace=e >/dev/null # perf script -i t1 --no-itrace -D | grep 'POKE\|KSYMBOL' 5 312216133258 0x8bafe0 [0x50]: PERF_RECORD_KSYMBOL addr ffffffffc0360000 len 415 type 2 flags 0x0 name ftrace_trampoline 5 312216133494 0x8bb030 [0x1d8]: PERF_RECORD_TEXT_POKE addr 0xffffffffc0360000 old len 0 new len 415 5 312216229563 0x8bb208 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffac6016f5 old len 5 new len 5 5 312216239063 0x8bb248 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffac601803 old len 5 new len 5 5 312216727230 0x8bb288 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffabbea190 old len 5 new len 5 5 312216739322 0x8bb2c8 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffac6016f5 old len 5 new len 5 5 312216748321 0x8bb308 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffac601803 old len 5 new len 5 7 313287163462 0x2817430 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffac6016f5 old len 5 new len 5 7 313287174890 0x2817470 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffac601803 old len 5 new len 5 7 313287818979 0x28174b0 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffabbea190 old len 5 new len 5 7 313287829357 0x28174f0 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffac6016f5 old len 5 new len 5 7 313287841246 0x2817530 [0x40]: PERF_RECORD_TEXT_POKE addr 0xffffffffac601803 old len 5 new len 5 Signed-off-by: Adrian Hunter Cc: Alexander Shishkin Cc: Borislav Petkov Cc: H. Peter Anvin Cc: Jiri Olsa Cc: Leo Yan Cc: Mark Rutland Cc: Masami Hiramatsu Cc: Mathieu Poirier Cc: Peter Zijlstra Cc: Steven Rostedt (VMware) Cc: x86@kernel.org Link: http://lore.kernel.org/lkml/20200512121922.8997-14-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/arch/x86/util/intel-pt.c | 4 ++ tools/perf/util/intel-pt.c | 75 +++++++++++++++++++++++++++++++++++++ 2 files changed, 79 insertions(+) (limited to 'tools/perf/util/intel-pt.c') diff --git a/tools/perf/arch/x86/util/intel-pt.c b/tools/perf/arch/x86/util/intel-pt.c index 6ce451293634..082e5f2a415a 100644 --- a/tools/perf/arch/x86/util/intel-pt.c +++ b/tools/perf/arch/x86/util/intel-pt.c @@ -837,6 +837,10 @@ static int intel_pt_recording_options(struct auxtrace_record *itr, } } + if (have_timing_info && !intel_pt_evsel->core.attr.exclude_kernel && + perf_can_record_text_poke_events() && perf_can_record_cpu_wide()) + opts->text_poke = true; + if (intel_pt_evsel) { /* * To obtain the auxtrace buffer file descriptor, the auxtrace diff --git a/tools/perf/util/intel-pt.c b/tools/perf/util/intel-pt.c index cb3c1e569a2d..6c7e44ac444d 100644 --- a/tools/perf/util/intel-pt.c +++ b/tools/perf/util/intel-pt.c @@ -520,6 +520,17 @@ intel_pt_cache_lookup(struct dso *dso, struct machine *machine, u64 offset) return auxtrace_cache__lookup(dso->auxtrace_cache, offset); } +static void intel_pt_cache_invalidate(struct dso *dso, struct machine *machine, + u64 offset) +{ + struct auxtrace_cache *c = intel_pt_cache(dso, machine); + + if (!c) + return; + + auxtrace_cache__remove(dso->auxtrace_cache, offset); +} + static inline u8 intel_pt_cpumode(struct intel_pt *pt, uint64_t ip) { return ip >= pt->kernel_start ? @@ -2594,6 +2605,67 @@ static int intel_pt_process_itrace_start(struct intel_pt *pt, event->itrace_start.tid); } +static int intel_pt_find_map(struct thread *thread, u8 cpumode, u64 addr, + struct addr_location *al) +{ + if (!al->map || addr < al->map->start || addr >= al->map->end) { + if (!thread__find_map(thread, cpumode, addr, al)) + return -1; + } + + return 0; +} + +/* Invalidate all instruction cache entries that overlap the text poke */ +static int intel_pt_text_poke(struct intel_pt *pt, union perf_event *event) +{ + u8 cpumode = event->header.misc & PERF_RECORD_MISC_CPUMODE_MASK; + u64 addr = event->text_poke.addr + event->text_poke.new_len - 1; + /* Assume text poke begins in a basic block no more than 4096 bytes */ + int cnt = 4096 + event->text_poke.new_len; + struct thread *thread = pt->unknown_thread; + struct addr_location al = { .map = NULL }; + struct machine *machine = pt->machine; + struct intel_pt_cache_entry *e; + u64 offset; + + if (!event->text_poke.new_len) + return 0; + + for (; cnt; cnt--, addr--) { + if (intel_pt_find_map(thread, cpumode, addr, &al)) { + if (addr < event->text_poke.addr) + return 0; + continue; + } + + if (!al.map->dso || !al.map->dso->auxtrace_cache) + continue; + + offset = al.map->map_ip(al.map, addr); + + e = intel_pt_cache_lookup(al.map->dso, machine, offset); + if (!e) + continue; + + if (addr + e->byte_cnt + e->length <= event->text_poke.addr) { + /* + * No overlap. Working backwards there cannot be another + * basic block that overlaps the text poke if there is a + * branch instruction before the text poke address. + */ + if (e->branch != INTEL_PT_BR_NO_BRANCH) + return 0; + } else { + intel_pt_cache_invalidate(al.map->dso, machine, offset); + intel_pt_log("Invalidated instruction cache for %s at %#"PRIx64"\n", + al.map->dso->long_name, addr); + } + } + + return 0; +} + static int intel_pt_process_event(struct perf_session *session, union perf_event *event, struct perf_sample *sample, @@ -2662,6 +2734,9 @@ static int intel_pt_process_event(struct perf_session *session, event->header.type == PERF_RECORD_SWITCH_CPU_WIDE) err = intel_pt_context_switch(pt, event, sample); + if (!err && event->header.type == PERF_RECORD_TEXT_POKE) + err = intel_pt_text_poke(pt, event); + intel_pt_log("event %u: cpu %d time %"PRIu64" tsc %#"PRIx64" ", event->header.type, sample->cpu, sample->time, timestamp); intel_pt_log_event(event); -- cgit v1.2.3 From 7eeb9855c1a4e6037bb1237a2a68ff1ee7aa4e67 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Tue, 12 May 2020 15:19:22 +0300 Subject: perf script: Show text poke address symbol It is generally more useful to show the symbol with an address. In this case, the print function requires the 'machine' which means changing callers to provide it as a parameter. It is optional because most events do not need it and the callers that matter can provide it. Committer notes: Made 'union perf_event' continue to be the first parameter to the perf_event__fprintf() and perf_event__fprintf_text_poke() events. Signed-off-by: Adrian Hunter Cc: Alexander Shishkin Cc: Borislav Petkov Cc: H. Peter Anvin Cc: Jiri Olsa Cc: Leo Yan Cc: Mark Rutland Cc: Masami Hiramatsu Cc: Mathieu Poirier Cc: Peter Zijlstra Cc: Steven Rostedt (VMware) Cc: x86@kernel.org Link: http://lore.kernel.org/lkml/20200512121922.8997-16-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-script.c | 4 ++-- tools/perf/tests/perf-record.c | 4 ++-- tools/perf/util/event.c | 21 ++++++++++++++++----- tools/perf/util/event.h | 4 ++-- tools/perf/util/intel-pt.c | 2 +- tools/perf/util/machine.c | 2 +- 6 files changed, 24 insertions(+), 13 deletions(-) (limited to 'tools/perf/util/intel-pt.c') diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c index bd81cc1b062e..0dfc38fb6d35 100644 --- a/tools/perf/builtin-script.c +++ b/tools/perf/builtin-script.c @@ -2178,7 +2178,7 @@ static int print_event_with_time(struct perf_tool *tool, event->header.type, stdout); } - perf_event__fprintf(event, stdout); + perf_event__fprintf(event, machine, stdout); thread__put(thread); @@ -2313,7 +2313,7 @@ process_finished_round_event(struct perf_tool *tool __maybe_unused, struct ordered_events *oe __maybe_unused) { - perf_event__fprintf(event, stdout); + perf_event__fprintf(event, NULL, stdout); return 0; } diff --git a/tools/perf/tests/perf-record.c b/tools/perf/tests/perf-record.c index 83adfd846ccd..67d3f5aad016 100644 --- a/tools/perf/tests/perf-record.c +++ b/tools/perf/tests/perf-record.c @@ -185,14 +185,14 @@ int test__PERF_RECORD(struct test *test __maybe_unused, int subtest __maybe_unus err = perf_evlist__parse_sample(evlist, event, &sample); if (err < 0) { if (verbose > 0) - perf_event__fprintf(event, stderr); + perf_event__fprintf(event, NULL, stderr); pr_debug("Couldn't parse sample\n"); goto out_delete_evlist; } if (verbose > 0) { pr_info("%" PRIu64" %d ", sample.time, sample.cpu); - perf_event__fprintf(event, stderr); + perf_event__fprintf(event, NULL, stderr); } if (prev_time > sample.time) { diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c index dde2f0147713..317a26571845 100644 --- a/tools/perf/util/event.c +++ b/tools/perf/util/event.c @@ -440,14 +440,25 @@ static int text_poke_printer(enum binary_printer_ops op, unsigned int val, } } -size_t perf_event__fprintf_text_poke(union perf_event *event, FILE *fp) +size_t perf_event__fprintf_text_poke(union perf_event *event, struct machine *machine, FILE *fp) { struct perf_record_text_poke_event *tp = &event->text_poke; size_t ret; bool old; - ret = fprintf(fp, " %" PRI_lx64 " old len %u new len %u\n", - tp->addr, tp->old_len, tp->new_len); + ret = fprintf(fp, " %" PRI_lx64 " ", tp->addr); + if (machine) { + struct addr_location al; + + al.map = maps__find(&machine->kmaps, tp->addr); + if (al.map && map__load(al.map) >= 0) { + al.addr = al.map->map_ip(al.map, tp->addr); + al.sym = map__find_symbol(al.map, al.addr); + if (al.sym) + ret += symbol__fprintf_symname_offs(al.sym, &al, fp); + } + } + ret += fprintf(fp, " old len %u new len %u\n", tp->old_len, tp->new_len); old = true; ret += binary__fprintf(tp->bytes, tp->old_len, 16, text_poke_printer, &old, fp); @@ -457,7 +468,7 @@ size_t perf_event__fprintf_text_poke(union perf_event *event, FILE *fp) return ret; } -size_t perf_event__fprintf(union perf_event *event, FILE *fp) +size_t perf_event__fprintf(union perf_event *event, struct machine *machine, FILE *fp) { size_t ret = fprintf(fp, "PERF_RECORD_%s", perf_event__name(event->header.type)); @@ -502,7 +513,7 @@ size_t perf_event__fprintf(union perf_event *event, FILE *fp) ret += perf_event__fprintf_bpf(event, fp); break; case PERF_RECORD_TEXT_POKE: - ret += perf_event__fprintf_text_poke(event, fp); + ret += perf_event__fprintf_text_poke(event, machine, fp); break; default: ret += fprintf(fp, "\n"); diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h index 3c4eb94f93de..b828b99176f4 100644 --- a/tools/perf/util/event.h +++ b/tools/perf/util/event.h @@ -389,8 +389,8 @@ size_t perf_event__fprintf_namespaces(union perf_event *event, FILE *fp); size_t perf_event__fprintf_cgroup(union perf_event *event, FILE *fp); size_t perf_event__fprintf_ksymbol(union perf_event *event, FILE *fp); size_t perf_event__fprintf_bpf(union perf_event *event, FILE *fp); -size_t perf_event__fprintf_text_poke(union perf_event *event, FILE *fp); -size_t perf_event__fprintf(union perf_event *event, FILE *fp); +size_t perf_event__fprintf_text_poke(union perf_event *event, struct machine *machine,FILE *fp); +size_t perf_event__fprintf(union perf_event *event, struct machine *machine, FILE *fp); int kallsyms__get_function_start(const char *kallsyms_filename, const char *symbol_name, u64 *addr); diff --git a/tools/perf/util/intel-pt.c b/tools/perf/util/intel-pt.c index 6c7e44ac444d..9cef46cfcf13 100644 --- a/tools/perf/util/intel-pt.c +++ b/tools/perf/util/intel-pt.c @@ -236,7 +236,7 @@ static void intel_pt_log_event(union perf_event *event) if (!intel_pt_enable_logging || !f) return; - perf_event__fprintf(event, f); + perf_event__fprintf(event, NULL, f); } static void intel_pt_dump_sample(struct perf_session *session, diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c index a81859532571..96af544eac8f 100644 --- a/tools/perf/util/machine.c +++ b/tools/perf/util/machine.c @@ -821,7 +821,7 @@ int machine__process_text_poke(struct machine *machine, union perf_event *event, u8 cpumode = event->header.misc & PERF_RECORD_MISC_CPUMODE_MASK; if (dump_trace) - perf_event__fprintf_text_poke(event, stdout); + perf_event__fprintf_text_poke(event, machine, stdout); if (!event->text_poke.new_len) return 0; -- cgit v1.2.3 From 1d846aeb86cc6e9db1cf08822404c95ecb8bd6c1 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Fri, 10 Jul 2020 18:10:58 +0300 Subject: perf intel-pt: Use itrace error flags to suppress some errors The itrace "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 Suppressing those errors can be useful for testing and debugging because they are not due to decoding. Signed-off-by: Adrian Hunter Reviewed-by: Andi Kleen Cc: Jiri Olsa Link: http://lore.kernel.org/lkml/20200710151104.15137-7-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-intel-pt.txt | 9 ++++++++- tools/perf/util/intel-pt.c | 9 +++++++++ 2 files changed, 17 insertions(+), 1 deletion(-) (limited to 'tools/perf/util/intel-pt.c') diff --git a/tools/perf/Documentation/perf-intel-pt.txt b/tools/perf/Documentation/perf-intel-pt.txt index f4cd49a7fcdb..20ac592a2641 100644 --- a/tools/perf/Documentation/perf-intel-pt.txt +++ b/tools/perf/Documentation/perf-intel-pt.txt @@ -871,7 +871,14 @@ Developer Manuals. Error events show where the decoder lost the trace. Error events are quite important. Users must know if what they are seeing is a complete -picture or not. +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 The "d" option will cause the creation of a file "intel_pt.log" containing all decoded packets and instructions. Note that this option slows down the decoder diff --git a/tools/perf/util/intel-pt.c b/tools/perf/util/intel-pt.c index 9cef46cfcf13..8b860a6f4ea9 100644 --- a/tools/perf/util/intel-pt.c +++ b/tools/perf/util/intel-pt.c @@ -1863,6 +1863,15 @@ static int intel_pt_synth_error(struct intel_pt *pt, int code, int cpu, char msg[MAX_AUXTRACE_ERROR_MSG]; int err; + if (pt->synth_opts.error_minus_flags) { + if (code == INTEL_PT_ERR_OVR && + pt->synth_opts.error_minus_flags & AUXTRACE_ERR_FLG_OVERFLOW) + return 0; + if (code == INTEL_PT_ERR_LOST && + pt->synth_opts.error_minus_flags & AUXTRACE_ERR_FLG_DATA_LOST) + return 0; + } + intel_pt__strerror(code, msg, MAX_AUXTRACE_ERROR_MSG); auxtrace_synth_error(&event.auxtrace_error, PERF_AUXTRACE_ERROR_ITRACE, -- cgit v1.2.3 From 8b83fccdd2fc91dfd6fc7ef6a804c1426f7a6216 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Fri, 10 Jul 2020 18:11:00 +0300 Subject: perf intel-pt: Use itrace debug log flags to suppress some messages 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 Suppressing perf events is useful for decreasing the size of the log. Signed-off-by: Adrian Hunter Reviewed-by: Andi Kleen Cc: Jiri Olsa Link: http://lore.kernel.org/lkml/20200710151104.15137-9-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-intel-pt.txt | 5 ++++- tools/perf/util/intel-pt.c | 17 ++++++++++------- 2 files changed, 14 insertions(+), 8 deletions(-) (limited to 'tools/perf/util/intel-pt.c') diff --git a/tools/perf/Documentation/perf-intel-pt.txt b/tools/perf/Documentation/perf-intel-pt.txt index 20ac592a2641..d22dead7bbe0 100644 --- a/tools/perf/Documentation/perf-intel-pt.txt +++ b/tools/perf/Documentation/perf-intel-pt.txt @@ -882,7 +882,10 @@ For example, for errors but not overflow or data lost errors: The "d" option will cause the creation of a file "intel_pt.log" containing all decoded packets and instructions. Note that this option slows down the decoder -and that the resulting file may be very large. +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 In addition, the period of the "instructions" event can be specified. e.g. diff --git a/tools/perf/util/intel-pt.c b/tools/perf/util/intel-pt.c index 8b860a6f4ea9..5f70f009d616 100644 --- a/tools/perf/util/intel-pt.c +++ b/tools/perf/util/intel-pt.c @@ -249,6 +249,11 @@ static void intel_pt_dump_sample(struct perf_session *session, intel_pt_dump(pt, sample->aux_sample.data, sample->aux_sample.size); } +static bool intel_pt_log_events(struct intel_pt *pt) +{ + return !(pt->synth_opts.log_minus_flags & AUXTRACE_LOG_FLG_ALL_PERF_EVTS); +} + static int intel_pt_do_fix_overlap(struct intel_pt *pt, struct auxtrace_buffer *a, struct auxtrace_buffer *b) { @@ -2586,10 +2591,6 @@ static int intel_pt_context_switch(struct intel_pt *pt, union perf_event *event, return -EINVAL; } - intel_pt_log("context_switch: cpu %d pid %d tid %d time %"PRIu64" tsc %#"PRIx64"\n", - cpu, pid, tid, sample->time, perf_time_to_tsc(sample->time, - &pt->tc)); - ret = intel_pt_sync_switch(pt, cpu, tid, sample->time); if (ret <= 0) return ret; @@ -2746,9 +2747,11 @@ static int intel_pt_process_event(struct perf_session *session, if (!err && event->header.type == PERF_RECORD_TEXT_POKE) err = intel_pt_text_poke(pt, event); - intel_pt_log("event %u: cpu %d time %"PRIu64" tsc %#"PRIx64" ", - event->header.type, sample->cpu, sample->time, timestamp); - intel_pt_log_event(event); + if (intel_pt_enable_logging && intel_pt_log_events(pt)) { + intel_pt_log("event %u: cpu %d time %"PRIu64" tsc %#"PRIx64" ", + event->header.type, sample->cpu, sample->time, timestamp); + intel_pt_log_event(event); + } return err; } -- cgit v1.2.3 From d4575f5fce71b47431a98096a9f74b7492854633 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Fri, 10 Jul 2020 18:11:01 +0300 Subject: perf intel-pt: Time filter logged perf events Change the debug logging (when used with the --time option) to time filter logged perf events, but allow that to be overridden by using "d+a" instead of plain "d". That can reduce the size of the log file. Signed-off-by: Adrian Hunter Reviewed-by: Andi Kleen Cc: Jiri Olsa Link: http://lore.kernel.org/lkml/20200710151104.15137-10-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-intel-pt.txt | 3 +++ tools/perf/util/intel-pt.c | 19 ++++++++++++++++--- 2 files changed, 19 insertions(+), 3 deletions(-) (limited to 'tools/perf/util/intel-pt.c') diff --git a/tools/perf/Documentation/perf-intel-pt.txt b/tools/perf/Documentation/perf-intel-pt.txt index d22dead7bbe0..4666e4a83615 100644 --- a/tools/perf/Documentation/perf-intel-pt.txt +++ b/tools/perf/Documentation/perf-intel-pt.txt @@ -886,6 +886,9 @@ 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 +By default, logged perf events are filtered by any specified time ranges, but +flag +a overrides that. In addition, the period of the "instructions" event can be specified. e.g. diff --git a/tools/perf/util/intel-pt.c b/tools/perf/util/intel-pt.c index 5f70f009d616..0715d6e23b2f 100644 --- a/tools/perf/util/intel-pt.c +++ b/tools/perf/util/intel-pt.c @@ -249,9 +249,22 @@ static void intel_pt_dump_sample(struct perf_session *session, intel_pt_dump(pt, sample->aux_sample.data, sample->aux_sample.size); } -static bool intel_pt_log_events(struct intel_pt *pt) +static bool intel_pt_log_events(struct intel_pt *pt, u64 tm) { - return !(pt->synth_opts.log_minus_flags & AUXTRACE_LOG_FLG_ALL_PERF_EVTS); + struct perf_time_interval *range = pt->synth_opts.ptime_range; + int n = pt->synth_opts.range_num; + + if (pt->synth_opts.log_plus_flags & AUXTRACE_LOG_FLG_ALL_PERF_EVTS) + return true; + + if (pt->synth_opts.log_minus_flags & AUXTRACE_LOG_FLG_ALL_PERF_EVTS) + return false; + + /* perf_time__ranges_skip_sample does not work if time is zero */ + if (!tm) + tm = 1; + + return !n || !perf_time__ranges_skip_sample(range, n, tm); } static int intel_pt_do_fix_overlap(struct intel_pt *pt, struct auxtrace_buffer *a, @@ -2747,7 +2760,7 @@ static int intel_pt_process_event(struct perf_session *session, if (!err && event->header.type == PERF_RECORD_TEXT_POKE) err = intel_pt_text_poke(pt, event); - if (intel_pt_enable_logging && intel_pt_log_events(pt)) { + if (intel_pt_enable_logging && intel_pt_log_events(pt, sample->time)) { intel_pt_log("event %u: cpu %d time %"PRIu64" tsc %#"PRIx64" ", event->header.type, sample->cpu, sample->time, timestamp); intel_pt_log_event(event); -- cgit v1.2.3 From 7c1b16ba0e26e6802d80c99c92529f29bcdcea25 Mon Sep 17 00:00:00 2001 From: Adrian Hunter Date: Fri, 10 Jul 2020 18:11:03 +0300 Subject: perf intel-pt: Add support for decoding FUP/TIP only Use the new itrace 'q' option to add support for a mode of decoding that ignores TNT, does not walk object code, but gets the ip from FUP and TIP packets. Example: $ perf record -e intel_pt//u grep -rI pudding drivers [ perf record: Woken up 52 times to write data ] [ perf record: Captured and wrote 57.870 MB perf.data ] $ time perf script --itrace=bi | wc -l 58948289 real 1m23.863s user 1m23.251s sys 0m7.452s $ time perf script --itrace=biq | wc -l 3385694 real 0m4.453s user 0m4.455s sys 0m0.328s Signed-off-by: Adrian Hunter Reviewed-by: Andi Kleen Tested-by: Arnaldo Carvalho de Melo Cc: Jiri Olsa Link: http://lore.kernel.org/lkml/20200710151104.15137-12-adrian.hunter@intel.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-intel-pt.txt | 31 ++++ .../perf/util/intel-pt-decoder/intel-pt-decoder.c | 167 ++++++++++++++++++++- .../perf/util/intel-pt-decoder/intel-pt-decoder.h | 1 + tools/perf/util/intel-pt.c | 6 +- 4 files changed, 200 insertions(+), 5 deletions(-) (limited to 'tools/perf/util/intel-pt.c') diff --git a/tools/perf/Documentation/perf-intel-pt.txt b/tools/perf/Documentation/perf-intel-pt.txt index 4666e4a83615..f9fe4a4040ba 100644 --- a/tools/perf/Documentation/perf-intel-pt.txt +++ b/tools/perf/Documentation/perf-intel-pt.txt @@ -825,6 +825,7 @@ The letters are: l synthesize last branch entries (use with i or x) L synthesize last branch entries on existing event records s skip initial number of events + q quicker (less detailed) decoding "Instructions" events look like they were recorded by "perf record -e instructions". @@ -969,6 +970,36 @@ at the beginning. This is useful to ignore initialization code. skips the first million instructions. +The q option changes the way the trace is decoded. The decoding is much faster +but much less detailed. Specifically, with the q option, the decoder does not +decode TNT packets, and does not walk object code, but gets the ip from FUP and +TIP packets. The q option can be used with the b and i options but the period +is not used. The q option decodes more quickly, but is useful only if the +control flow of interest is represented or indicated by FUP, TIP, TIP.PGE, or +TIP.PGD packets (refer below). However the q option could be used to find time +ranges that could then be decoded fully using the --time option. + +What will *not* be decoded with the (single) q option: + + - direct calls and jmps + - conditional branches + - non-branch instructions + +What *will* be decoded with the (single) q option: + + - asynchronous branches such as interrupts + - indirect branches + - function return target address *if* the noretcomp config term (refer + config terms section) was used + - start of (control-flow) tracing + - end of (control-flow) tracing, if it is not out of context + - power events, ptwrite, transaction start and abort + - instruction pointer associated with PSB packets + +Note the q option does not specify what events will be synthesized e.g. the p +option must be used also to show power events. + + dump option ~~~~~~~~~~~ diff --git a/tools/perf/util/intel-pt-decoder/intel-pt-decoder.c b/tools/perf/util/intel-pt-decoder/intel-pt-decoder.c index 7ffcbd6fcd1a..ccb204b1a050 100644 --- a/tools/perf/util/intel-pt-decoder/intel-pt-decoder.c +++ b/tools/perf/util/intel-pt-decoder/intel-pt-decoder.c @@ -55,6 +55,7 @@ enum intel_pt_pkt_state { INTEL_PT_STATE_TIP_PGD, INTEL_PT_STATE_FUP, INTEL_PT_STATE_FUP_NO_TIP, + INTEL_PT_STATE_RESAMPLE, }; static inline bool intel_pt_sample_time(enum intel_pt_pkt_state pkt_state) @@ -65,6 +66,7 @@ static inline bool intel_pt_sample_time(enum intel_pt_pkt_state pkt_state) case INTEL_PT_STATE_ERR_RESYNC: case INTEL_PT_STATE_IN_SYNC: case INTEL_PT_STATE_TNT_CONT: + case INTEL_PT_STATE_RESAMPLE: return true; case INTEL_PT_STATE_TNT: case INTEL_PT_STATE_TIP: @@ -109,6 +111,8 @@ struct intel_pt_decoder { bool fixup_last_mtc; bool have_last_ip; bool in_psb; + bool hop; + bool hop_psb_fup; enum intel_pt_param_flags flags; uint64_t pos; uint64_t last_ip; @@ -235,6 +239,7 @@ struct intel_pt_decoder *intel_pt_decoder_new(struct intel_pt_params *params) decoder->data = params->data; decoder->return_compression = params->return_compression; decoder->branch_enable = params->branch_enable; + decoder->hop = params->quick >= 1; decoder->flags = params->flags; @@ -275,6 +280,9 @@ struct intel_pt_decoder *intel_pt_decoder_new(struct intel_pt_params *params) intel_pt_log("timestamp: tsc_ctc_mult %u\n", decoder->tsc_ctc_mult); intel_pt_log("timestamp: tsc_slip %#x\n", decoder->tsc_slip); + if (decoder->hop) + intel_pt_log("Hop mode: decoding FUP and TIPs, but not TNT\n"); + return decoder; } @@ -1730,8 +1738,14 @@ static int intel_pt_walk_psbend(struct intel_pt_decoder *decoder) case INTEL_PT_FUP: decoder->pge = true; - if (decoder->packet.count) + if (decoder->packet.count) { intel_pt_set_last_ip(decoder); + if (decoder->hop) { + /* Act on FUP at PSBEND */ + decoder->ip = decoder->last_ip; + decoder->hop_psb_fup = true; + } + } break; case INTEL_PT_MODE_TSX: @@ -1875,6 +1889,118 @@ static int intel_pt_walk_fup_tip(struct intel_pt_decoder *decoder) } } +static int intel_pt_resample(struct intel_pt_decoder *decoder) +{ + decoder->pkt_state = INTEL_PT_STATE_IN_SYNC; + decoder->state.type = INTEL_PT_INSTRUCTION; + decoder->state.from_ip = decoder->ip; + decoder->state.to_ip = 0; + return 0; +} + +#define HOP_PROCESS 0 +#define HOP_IGNORE 1 +#define HOP_RETURN 2 +#define HOP_AGAIN 3 + +/* Hop mode: Ignore TNT, do not walk code, but get ip from FUPs and TIPs */ +static int intel_pt_hop_trace(struct intel_pt_decoder *decoder, bool *no_tip, int *err) +{ + switch (decoder->packet.type) { + case INTEL_PT_TNT: + return HOP_IGNORE; + + case INTEL_PT_TIP_PGD: + if (!decoder->packet.count) + return HOP_IGNORE; + intel_pt_set_ip(decoder); + decoder->state.type |= INTEL_PT_TRACE_END; + decoder->state.from_ip = 0; + decoder->state.to_ip = decoder->ip; + return HOP_RETURN; + + case INTEL_PT_TIP: + if (!decoder->packet.count) + return HOP_IGNORE; + intel_pt_set_ip(decoder); + decoder->state.type = INTEL_PT_INSTRUCTION; + decoder->state.from_ip = decoder->ip; + decoder->state.to_ip = 0; + return HOP_RETURN; + + case INTEL_PT_FUP: + if (!decoder->packet.count) + return HOP_IGNORE; + intel_pt_set_ip(decoder); + if (intel_pt_fup_event(decoder)) + return HOP_RETURN; + if (!decoder->branch_enable) + *no_tip = true; + if (*no_tip) { + decoder->state.type = INTEL_PT_INSTRUCTION; + decoder->state.from_ip = decoder->ip; + decoder->state.to_ip = 0; + return HOP_RETURN; + } + *err = intel_pt_walk_fup_tip(decoder); + if (!*err) + decoder->pkt_state = INTEL_PT_STATE_RESAMPLE; + return HOP_RETURN; + + case INTEL_PT_PSB: + decoder->last_ip = 0; + decoder->have_last_ip = true; + decoder->hop_psb_fup = false; + *err = intel_pt_walk_psbend(decoder); + if (*err == -EAGAIN) + return HOP_AGAIN; + if (*err) + return HOP_RETURN; + if (decoder->hop_psb_fup) { + decoder->hop_psb_fup = false; + decoder->state.type = INTEL_PT_INSTRUCTION; + decoder->state.from_ip = decoder->ip; + decoder->state.to_ip = 0; + return HOP_RETURN; + } + if (decoder->cbr != decoder->cbr_seen) { + decoder->state.type = 0; + return HOP_RETURN; + } + return HOP_IGNORE; + + case INTEL_PT_BAD: + case INTEL_PT_PAD: + case INTEL_PT_TIP_PGE: + case INTEL_PT_TSC: + case INTEL_PT_TMA: + case INTEL_PT_MODE_EXEC: + case INTEL_PT_MODE_TSX: + case INTEL_PT_MTC: + case INTEL_PT_CYC: + case INTEL_PT_VMCS: + case INTEL_PT_PSBEND: + case INTEL_PT_CBR: + case INTEL_PT_TRACESTOP: + case INTEL_PT_PIP: + case INTEL_PT_OVF: + case INTEL_PT_MNT: + case INTEL_PT_PTWRITE: + case INTEL_PT_PTWRITE_IP: + case INTEL_PT_EXSTOP: + case INTEL_PT_EXSTOP_IP: + case INTEL_PT_MWAIT: + case INTEL_PT_PWRE: + case INTEL_PT_PWRX: + case INTEL_PT_BBP: + case INTEL_PT_BIP: + case INTEL_PT_BEP: + case INTEL_PT_BEP_IP: + default: + return HOP_PROCESS; + } +} + static int intel_pt_walk_trace(struct intel_pt_decoder *decoder) { bool no_tip = false; @@ -1885,6 +2011,19 @@ static int intel_pt_walk_trace(struct intel_pt_decoder *decoder) if (err) return err; next: + if (decoder->hop) { + switch (intel_pt_hop_trace(decoder, &no_tip, &err)) { + case HOP_IGNORE: + continue; + case HOP_RETURN: + return err; + case HOP_AGAIN: + goto next; + default: + break; + } + } + switch (decoder->packet.type) { case INTEL_PT_TNT: if (!decoder->packet.count) @@ -1914,6 +2053,12 @@ next: decoder->state.from_ip = 0; decoder->state.to_ip = decoder->ip; decoder->state.type |= INTEL_PT_TRACE_BEGIN; + /* + * In hop mode, resample to get the to_ip as an + * "instruction" sample. + */ + if (decoder->hop) + decoder->pkt_state = INTEL_PT_STATE_RESAMPLE; return 0; } @@ -2033,7 +2178,7 @@ next: case INTEL_PT_MODE_TSX: /* MODE_TSX need not be followed by FUP */ - if (!decoder->pge) { + if (!decoder->pge || decoder->in_psb) { intel_pt_update_in_tx(decoder); break; } @@ -2424,7 +2569,11 @@ static int intel_pt_sync_ip(struct intel_pt_decoder *decoder) if (err) return err; - decoder->pkt_state = INTEL_PT_STATE_IN_SYNC; + /* In hop mode, resample to get the to_ip as an "instruction" sample */ + if (decoder->hop) + decoder->pkt_state = INTEL_PT_STATE_RESAMPLE; + else + decoder->pkt_state = INTEL_PT_STATE_IN_SYNC; decoder->overflow = false; decoder->state.from_ip = 0; @@ -2545,7 +2694,14 @@ static int intel_pt_sync(struct intel_pt_decoder *decoder) if (decoder->ip) { decoder->state.type = 0; /* Do not have a sample */ - decoder->pkt_state = INTEL_PT_STATE_IN_SYNC; + /* + * In hop mode, resample to get the PSB FUP ip as an + * "instruction" sample. + */ + if (decoder->hop) + decoder->pkt_state = INTEL_PT_STATE_RESAMPLE; + else + decoder->pkt_state = INTEL_PT_STATE_IN_SYNC; } else { return intel_pt_sync_ip(decoder); } @@ -2609,6 +2765,9 @@ const struct intel_pt_state *intel_pt_decode(struct intel_pt_decoder *decoder) if (err == -EAGAIN) err = intel_pt_walk_trace(decoder); break; + case INTEL_PT_STATE_RESAMPLE: + err = intel_pt_resample(decoder); + break; default: err = intel_pt_bug(decoder); break; diff --git a/tools/perf/util/intel-pt-decoder/intel-pt-decoder.h b/tools/perf/util/intel-pt-decoder/intel-pt-decoder.h index e289e463d635..8645fc265481 100644 --- a/tools/perf/util/intel-pt-decoder/intel-pt-decoder.h +++ b/tools/perf/util/intel-pt-decoder/intel-pt-decoder.h @@ -250,6 +250,7 @@ struct intel_pt_params { uint32_t tsc_ctc_ratio_n; uint32_t tsc_ctc_ratio_d; enum intel_pt_param_flags flags; + unsigned int quick; }; struct intel_pt_decoder; diff --git a/tools/perf/util/intel-pt.c b/tools/perf/util/intel-pt.c index 0715d6e23b2f..2a8d245351e7 100644 --- a/tools/perf/util/intel-pt.c +++ b/tools/perf/util/intel-pt.c @@ -1030,6 +1030,7 @@ static struct intel_pt_queue *intel_pt_alloc_queue(struct intel_pt *pt, params.mtc_period = intel_pt_mtc_period(pt); params.tsc_ctc_ratio_n = pt->tsc_ctc_ratio_n; params.tsc_ctc_ratio_d = pt->tsc_ctc_ratio_d; + params.quick = pt->synth_opts.quick; if (pt->filts.cnt > 0) params.pgd_ip = intel_pt_pgd_ip; @@ -1423,7 +1424,10 @@ static int intel_pt_synth_instruction_sample(struct intel_pt_queue *ptq) sample.id = ptq->pt->instructions_id; sample.stream_id = ptq->pt->instructions_id; - sample.period = ptq->state->tot_insn_cnt - ptq->last_insn_cnt; + if (pt->synth_opts.quick) + sample.period = 1; + else + sample.period = ptq->state->tot_insn_cnt - ptq->last_insn_cnt; sample.cyc_cnt = ptq->ipc_cyc_cnt - ptq->last_in_cyc_cnt; if (sample.cyc_cnt) { -- cgit v1.2.3