[RFC] Don't print sample_type bits in non-group events not set in the group's was Re: [PATCH] perf, script: Fix crash with printing mixed trace point and other events

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

Em Fri, Jan 18, 2019 at 10:01:06AM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Fri, Jan 18, 2019 at 09:59:20AM -0300, Arnaldo Carvalho de Melo escreveu:
> > Thanks, tested and applied.

> > While testing I found something odd, the cycles events are not showing
> > the CPU and the probe events shows a "negative" CPU column,
> > investigating.
 
> The sample_type for those two events:
 
> [root@quaco wb]# perf evlist -v
> cpu/cpu-cycles,period=10000/: type: 4, size: 112, config: 0x3c, { sample_period, sample_freq }: 10000, sample_type: IP|TID|TIME|READ|IDENTIFIER, read_format: ID|GROUP, disabled: 1, mmap: 1, comm: 1, enable_on_exec: 1, task: 1, sample_id_all: 1, exclude_guest: 1, mmap2: 1, comm_exec: 1
> probe_libc:malloc: type: 2, size: 112, config: 0x790, sample_type: IP|TID|TIME|READ|CPU|PERIOD|RAW|IDENTIFIER, read_format: ID|GROUP, sample_id_all: 1, exclude_guest: 1
> # Tip: use 'perf evlist --trace-fields' to show fields for tracepoint events
> [root@quaco wb]#

The output:

  # perf probe -l
   probe_libc:malloc    (on __libc_malloc@malloc/malloc.c in /usr/lib64/libc-2.28.so)
   # perf record -e '{cpu/cpu-cycles,period=10000/,probe_libc:*}:S' sleep 1
   [ perf record: Woken up 1 times to write data ]
   [ perf record: Captured and wrote 0.023 MB perf.data (40 samples) ]
   # perf script
   Segmentation fault (core dumped)
   ^C
   #
 
 After:
 
   # perf script | head -6
      sleep 2888 94796.944981: 16198 cpu/cpu-cycles,period=10000/: ffffffff925dc04f get_random_u32+0x1f (/lib/modules/5.0.0-rc2+/build/vmlinux)
      sleep 2888 [-01] 94796.944981: probe_libc:malloc:
      sleep 2888 94796.944983:  4713 cpu/cpu-cycles,period=10000/: ffffffff922763af change_protection+0xcf (/lib/modules/5.0.0-rc2+/build/vmlinux)
      sleep 2888 [-01] 94796.944983: probe_libc:malloc:
      sleep 2888 94796.944986:  9934 cpu/cpu-cycles,period=10000/: ffffffff922777e0 move_page_tables+0x0 (/lib/modules/5.0.0-rc2+/build/vmlinux)
      sleep 2888 [-01] 94796.944986: probe_libc:malloc:
   #

For perf_sample->cpu to come out as -1 from perf_evsen__parse_sample() we would
have to have evsel->attr.sample_type not having PERF_SAMPLE_CPU set, which,
according to the 'perf evlist' output above, is not the case for
probe_libc:malloc...

So, this is because in this case we have it in a group so we end up never calling
perf_evsel__parse_sample for that probe_libc:malloc event, using the perf_sample
parsed for the cpu/cpu-cycles/ event that indeed doesn't have CPU set.

So we need to auto-deselect the CPU printing for non group events if the group
event doesn't have PERF_SAMPLE_CPU set, right Jiri?

See the details:

(gdb) b deliver_sample_value
Breakpoint 1 at 0x539a81: file util/session.c, line 1177.
(gdb) run script
Starting program: /root/bin/perf script
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[Detaching after fork from child process 20014]

Breakpoint 1, deliver_sample_value (evlist=0xab2ce0, tool=0x7fffffffc3e0, event=0x7ffff7fcd408, sample=0x7fffffffbd50, v=0x7ffff7fcd438,
    machine=0xaaca60) at util/session.c:1177
1177	{
(gdb) bt
#0  deliver_sample_value (evlist=0xab2ce0, tool=0x7fffffffc3e0, event=0x7ffff7fcd408, sample=0x7fffffffbd50, v=0x7ffff7fcd438, machine=0xaaca60)
    at util/session.c:1177
#1  0x0000000000539bc6 in deliver_sample_group (evlist=0xab2ce0, tool=0x7fffffffc3e0, event=0x7ffff7fcd408, sample=0x7fffffffbd50,
    machine=0xaaca60) at util/session.c:1205
#2  0x0000000000539c9e in perf_evlist__deliver_sample (evlist=0xab2ce0, tool=0x7fffffffc3e0, event=0x7ffff7fcd408, sample=0x7fffffffbd50,
    evsel=0xab3730, machine=0xaaca60) at util/session.c:1233
#3  0x0000000000539e05 in machines__deliver_event (machines=0xaaca60, evlist=0xab2ce0, event=0x7ffff7fcd408, sample=0x7fffffffbd50,
    tool=0x7fffffffc3e0, file_offset=21512) at util/session.c:1266
#4  0x000000000053a219 in perf_session__deliver_event (session=0xaac960, event=0x7ffff7fcd408, tool=0x7fffffffc3e0, file_offset=21512)
    at util/session.c:1335
#5  0x0000000000536d22 in ordered_events__deliver_event (oe=0xab2bf0, event=0xad1da8) at util/session.c:113
#6  0x000000000053da1c in do_flush (oe=0xab2bf0, show_progress=true) at util/ordered-events.c:243
#7  0x000000000053dd4b in __ordered_events__flush (oe=0xab2bf0, how=OE_FLUSH__FINAL, timestamp=0) at util/ordered-events.c:320
#8  0x000000000053de20 in ordered_events__flush (oe=0xab2bf0, how=OE_FLUSH__FINAL) at util/ordered-events.c:338
#9  0x000000000053bb5c in __perf_session__process_events (session=0xaac960, data_offset=488, data_size=23424, file_size=23912)
    at util/session.c:1925
#10 0x000000000053bca5 in perf_session__process_events (session=0xaac960) at util/session.c:1955
#11 0x0000000000463d3e in __cmd_script (script=0x7fffffffc3e0) at builtin-script.c:2388
#12 0x0000000000468140 in cmd_script (argc=0, argv=0x7fffffffdb40) at builtin-script.c:3727
#13 0x00000000004d4a1a in run_builtin (p=0x92ab18 <commands+408>, argc=1, argv=0x7fffffffdb40) at perf.c:302
#14 0x00000000004d4c87 in handle_internal_command (argc=1, argv=0x7fffffffdb40) at perf.c:354
#15 0x00000000004d4dd6 in run_argv (argcp=0x7fffffffd99c, argv=0x7fffffffd990) at perf.c:398
#16 0x00000000004d5142 in main (argc=1, argv=0x7fffffffdb40) at perf.c:520
(gdb) p (int)sample->cpu
$1 = -1
(gdb) info b
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   0x0000000000539a81 in deliver_sample_value at util/session.c:1177
	breakpoint already hit 1 time
(gdb) condition 1 (int)sample->cpu != -1
(gdb) c
Continuing.
    sleep  2888 94796.944981:      16198 cpu/cpu-cycles,period=10000/:  ffffffff925dc04f get_random_u32+0x1f (/lib/modules/5.0.0-rc2+/buil>
    sleep  2888 [-01] 94796.944981:            probe_libc:malloc:
    sleep  2888 94796.944983:       4713 cpu/cpu-cycles,period=10000/:  ffffffff922763af change_protection+0xcf (/lib/modules/5.0.0-rc2+/b>
    sleep  2888 [-01] 94796.944983:            probe_libc:malloc:
<SNIP>
[Inferior 1 (process 20003) exited normally]
(gdb)


See? None of the perf_sample parsed have perf_sample->cpu set, its all -1, which
is set in perf_evsel__parse_sample() to indicate that PERF_SAMPLE_TYPE wasn't found
in evsel->attr.sample_type for the evsel being used to parse the perf_event payload.

- Arnaldo