Messages in this thread | | | Date | Tue, 25 Oct 2022 17:45:53 -0300 | From | Arnaldo Carvalho de Melo <> | Subject | Re: [PATCH] perf scripts python: intel-pt-events.py: Add ability interleave output |
| |
Em Thu, Oct 20, 2022 at 06:25:09PM +0300, Adrian Hunter escreveu: > Intel PT timestamps are not provided for every branch, let alone every > instruction, so there can be many samples with the same timestamp. With > per-cpu contexts, decoding is done for each CPU in turn, which can make it > difficult to see what is happening on different CPUs at the same time. > Currently the interleaving from perf script --itrace=i0ns is quite coarse > grained. There are often long stretches executing on one CPU and nothing on > another.
Thanks, applied.
- Arnaldo
> Some people are interested in seeing what happened on multiple CPUs before > a crash to debug races etc. > > To improve perf script interleaving for parallel execution, the > intel-pt-events.py script has been enhanced to enable interleaving the > output with the same timestamp from different CPUs. It is understood that > interleaving is not perfect or causal. > > Add parameter --interleave [<n>] to interleave sample output for the same > timestamp so that no more than n samples for a CPU are displayed in a row. > 'n' defaults to 4. Note this only affects the order of output, and only > when the timestamp is the same. > > Example: > > $ perf script intel-pt-events.py --insn-trace --interleave 3 > ... > bash 2267/2267 [004] 9323.692625625 563caa3c86f0 jz 0x563caa3c89c7 run_pending_traps+0x30 (/usr/bin/bash) IPC: 1.52 (38/25) > bash 2267/2267 [004] 9323.692625625 563caa3c89c7 movq 0x118(%rsp), %rax run_pending_traps+0x307 (/usr/bin/bash) > bash 2267/2267 [004] 9323.692625625 563caa3c89cf subq %fs:0x28, %rax run_pending_traps+0x30f (/usr/bin/bash) > bash 2270/2270 [007] 9323.692625625 55dc58cabf02 jz 0x55dc58cabf48 unquoted_glob_pattern_p+0x102 (/usr/bin/bash) IPC: 1.56 (25/16) > bash 2270/2270 [007] 9323.692625625 55dc58cabf04 cmp $0x5d, %al unquoted_glob_pattern_p+0x104 (/usr/bin/bash) > bash 2270/2270 [007] 9323.692625625 55dc58cabf06 jnz 0x55dc58cabf10 unquoted_glob_pattern_p+0x106 (/usr/bin/bash) > bash 2264/2264 [001] 9323.692625625 7fd556a4376c jbe 0x7fd556a43ac8 round_and_return+0x3fc (/usr/lib/x86_64-linux-gnu/libc.so.6) IPC: 4.30 (43/10) > bash 2264/2264 [001] 9323.692625625 7fd556a43772 and $0x8, %edx round_and_return+0x402 (/usr/lib/x86_64-linux-gnu/libc.so.6) > bash 2264/2264 [001] 9323.692625625 7fd556a43775 jnz 0x7fd556a43ac8 round_and_return+0x405 (/usr/lib/x86_64-linux-gnu/libc.so.6) > bash 2267/2267 [004] 9323.692625625 563caa3c89d8 jnz 0x563caa3c8b11 run_pending_traps+0x318 (/usr/bin/bash) > bash 2267/2267 [004] 9323.692625625 563caa3c89de add $0x128, %rsp run_pending_traps+0x31e (/usr/bin/bash) > bash 2267/2267 [004] 9323.692625625 563caa3c89e5 popq %rbx run_pending_traps+0x325 (/usr/bin/bash) > ... > > Signed-off-by: Adrian Hunter <adrian.hunter@intel.com> > --- > tools/perf/Documentation/perf-intel-pt.txt | 12 +++- > tools/perf/scripts/python/intel-pt-events.py | 65 +++++++++++++++++++- > 2 files changed, 74 insertions(+), 3 deletions(-) > > diff --git a/tools/perf/Documentation/perf-intel-pt.txt b/tools/perf/Documentation/perf-intel-pt.txt > index 92464a5d7eaf..7b6ccd2fa3bf 100644 > --- a/tools/perf/Documentation/perf-intel-pt.txt > +++ b/tools/perf/Documentation/perf-intel-pt.txt > @@ -189,8 +189,16 @@ There is also script intel-pt-events.py which provides an example of how to > unpack the raw data for power events and PTWRITE. The script also displays > branches, and supports 2 additional modes selected by option: > > - --insn-trace - instruction trace > - --src-trace - source trace > + - --insn-trace - instruction trace > + - --src-trace - source trace > + > +The intel-pt-events.py script also has options: > + > + - --all-switch-events - display all switch events, not only the last consecutive. > + - --interleave [<n>] - interleave sample output for the same timestamp so that > + no more than n samples for a CPU are displayed in a row. 'n' defaults to 4. > + Note this only affects the order of output, and only when the timestamp is the > + same. > > As mentioned above, it is easy to capture too much data. One way to limit the > data captured is to use 'snapshot' mode which is explained further below. > diff --git a/tools/perf/scripts/python/intel-pt-events.py b/tools/perf/scripts/python/intel-pt-events.py > index 6be7fd8fd615..08862a2582f4 100644 > --- a/tools/perf/scripts/python/intel-pt-events.py > +++ b/tools/perf/scripts/python/intel-pt-events.py > @@ -13,10 +13,12 @@ > > from __future__ import print_function > > +import io > import os > import sys > import struct > import argparse > +import contextlib > > from libxed import LibXED > from ctypes import create_string_buffer, addressof > @@ -39,6 +41,11 @@ glb_src = False > glb_source_file_name = None > glb_line_number = None > glb_dso = None > +glb_stash_dict = {} > +glb_output = None > +glb_output_pos = 0 > +glb_cpu = -1 > +glb_time = 0 > > def get_optional_null(perf_dict, field): > if field in perf_dict: > @@ -70,6 +77,7 @@ def trace_begin(): > ap.add_argument("--insn-trace", action='store_true') > ap.add_argument("--src-trace", action='store_true') > ap.add_argument("--all-switch-events", action='store_true') > + ap.add_argument("--interleave", type=int, nargs='?', const=4, default=0) > global glb_args > global glb_insn > global glb_src > @@ -94,11 +102,39 @@ def trace_begin(): > perf_set_itrace_options(perf_script_context, itrace) > > def trace_end(): > + if glb_args.interleave: > + flush_stashed_output() > print("End") > > def trace_unhandled(event_name, context, event_fields_dict): > print(' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())])) > > +def stash_output(): > + global glb_stash_dict > + global glb_output_pos > + output_str = glb_output.getvalue()[glb_output_pos:] > + n = len(output_str) > + if n: > + glb_output_pos += n > + if glb_cpu not in glb_stash_dict: > + glb_stash_dict[glb_cpu] = [] > + glb_stash_dict[glb_cpu].append(output_str) > + > +def flush_stashed_output(): > + global glb_stash_dict > + while glb_stash_dict: > + cpus = list(glb_stash_dict.keys()) > + # Output at most glb_args.interleave output strings per cpu > + for cpu in cpus: > + items = glb_stash_dict[cpu] > + countdown = glb_args.interleave > + while len(items) and countdown: > + sys.stdout.write(items[0]) > + del items[0] > + countdown -= 1 > + if not items: > + del glb_stash_dict[cpu] > + > def print_ptwrite(raw_buf): > data = struct.unpack_from("<IQ", raw_buf) > flags = data[0] > @@ -375,15 +411,40 @@ def do_process_event(param_dict): > print_common_start(comm, sample, name) > print_common_ip(param_dict, sample, symbol, dso) > > +def interleave_events(param_dict): > + global glb_cpu > + global glb_time > + global glb_output > + global glb_output_pos > + > + sample = param_dict["sample"] > + glb_cpu = sample["cpu"] > + ts = sample["time"] > + > + if glb_time != ts: > + glb_time = ts > + flush_stashed_output() > + > + glb_output_pos = 0 > + with contextlib.redirect_stdout(io.StringIO()) as glb_output: > + do_process_event(param_dict) > + > + stash_output() > + > def process_event(param_dict): > try: > - do_process_event(param_dict) > + if glb_args.interleave: > + interleave_events(param_dict) > + else: > + do_process_event(param_dict) > except broken_pipe_exception: > # Stop python printing broken pipe errors and traceback > sys.stdout = open(os.devnull, 'w') > sys.exit(1) > > def auxtrace_error(typ, code, cpu, pid, tid, ip, ts, msg, cpumode, *x): > + if glb_args.interleave: > + flush_stashed_output() > if len(x) >= 2 and x[0]: > machine_pid = x[0] > vcpu = x[1] > @@ -403,6 +464,8 @@ def auxtrace_error(typ, code, cpu, pid, tid, ip, ts, msg, cpumode, *x): > sys.exit(1) > > def context_switch(ts, cpu, pid, tid, np_pid, np_tid, machine_pid, out, out_preempt, *x): > + if glb_args.interleave: > + flush_stashed_output() > if out: > out_str = "Switch out " > else: > -- > 2.34.1
--
- Arnaldo
| |