Re: [PATCH] perf scripts python: intel-pt-events.py: Add ability interleave output

[Arnaldo Carvalho de Melo <acme@kernel.org>]

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