Re: [PATCH 05/11] perf data: Add tracepoint events fields CTF conversion support

[Jiri Olsa <jolsa@redhat.com>]

On Wed, Feb 25, 2015 at 04:23:44PM -0300, Arnaldo Carvalho de Melo wrote:
> Em Fri, Feb 20, 2015 at 11:17:02PM +0100, Jiri Olsa escreveu:
> > From: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> > Adding support to convert tracepoint event fields into CTF
> > event fields.
>  
> > We parse each tracepoint event for CTF conversion and add
> > tracepoint fields as regular CTF event fields, so they
> > appear in babeltrace output like:
>  
> >   $ babeltrace ./ctf-data/
> >   ...
> >   [09:02:00.950703057] (+?.?????????) sched:sched_stat_runtime: { }, { perf_ip = ... SNIP ... common_type = 298, common_flags = 1, \
> >   common_preempt_count = 0, common_pid = 31813, comm = "perf", pid = 31813, runtime = 458800, vruntime = 52059858071 }
> >   ...
> 
> Processed the previous patches, everything ok:
> 
> [acme@ssdandy linux]$ ls -la perf.data
> ls: cannot access perf.data: No such file or directory
> [acme@ssdandy linux]$ trace record usleep 1
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.029 MB perf.data (88 samples) ]
> [acme@ssdandy linux]$ ls -la perf.data
> -rw-------. 1 acme acme 5399896 Fev 25 16:19 perf.data
> [acme@ssdandy linux]$ perf evlist
> raw_syscalls:sys_enter
> raw_syscalls:sys_exit
> [acme@ssdandy linux]$ perf evlist -v
> raw_syscalls:sys_enter: sample_freq=1, type: 2, config: 75, size: 104, sample_type: IP|TID|TIME|ID|CPU|PERIOD|RAW, read_format: ID, disabled: 1, inherit: 1, mmap: 1, mmap2: 1, comm: 1, comm_exec: 1, enable_on_exec: 1, task: 1, sample_id_all: 1, exclude_guest: 1
> raw_syscalls:sys_exit: sample_freq=1, type: 2, config: 74, size: 104, sample_type: IP|TID|TIME|ID|CPU|PERIOD|RAW, read_format: ID, disabled: 1, inherit: 1, enable_on_exec: 1, sample_id_all: 1, exclude_guest: 1
> [acme@ssdandy linux]$ perf data convert --to-ctf=./ctf-data/
> [ perf data convert: Converted 'perf.data' into CTF data './ctf-data/' ]
> [ perf data convert: Converted and wrote 0.009 MB (88 samples) ]
> [acme@ssdandy linux]$ babeltrace ./ctf-data/
> [23:48:47.557933780] (+?.?????????) raw_syscalls:sys_exit: { }, { perf_ip = 0xFFFFFFFF81020FBA, perf_tid = 5093, perf_pid = 5093, perf_id = 1512, perf_cpu = 3, perf_period = 1 }
> [23:48:47.557957461] (+0.000023681) raw_syscalls:sys_enter: { }, { perf_ip = 0xFFFFFFFF81020EA6, perf_tid = 5093, perf_pid = 5093, perf_id = 1504, perf_cpu = 3, perf_period = 1 }
> [23:48:47.557958406] (+0.000000945) raw_syscalls:sys_exit: { }, { perf_ip = 0xFFFFFFFF81020FBA, perf_tid = 5093, perf_pid = 5093, perf_id = 1512, perf_cpu = 3, perf_period = 1 }
> [23:48:47.557973567] (+0.000015161) raw_syscalls:sys_enter: { }, { perf_ip = 0xFFFFFFFF81020EA6, perf_tid = 5093, perf_pid = 5093, perf_id = 1504, perf_cpu = 3, perf_period = 1 }
> [23:48:47.557976047] (+0.000002480) raw_syscalls:sys_exit: { }, { perf_ip = 0xFFFFFFFF81020FBA, perf_tid = 5093, perf_pid = 5093, perf_id = 1512, perf_cpu = 3, perf_period = 1 }
> [23:48:47.557985774] (+0.000009727) raw_syscalls:sys_enter: { }, { perf_ip = 0xFFFFFFFF81020EA6, perf_tid = 5093, perf_pid = 5093, perf_id = 1504, perf_cpu = 3, perf_period = 1 }
> [23:48:47.557990826] (+0.000005052) raw_syscalls:sys_exit: { }, { perf_ip = 0xFFFFFFFF81020FBA, perf_tid = 5093, perf_pid = 5093, perf_id = 1512, perf_cpu = 3, perf_period = 1 }
> <SNIP>
> 
> But then I apply this patch (convert tracepoint events fields into CTF event fields) and:
> 
> [acme@ssdandy linux]$ perf data convert --to-ctf=./ctf-data/
> [ perf data convert: Converted 'perf.data' into CTF data './ctf-data/' ]
> [ perf data convert: Converted and wrote 0.009 MB (88 samples) ]
> [acme@ssdandy linux]$ babeltrace ./ctf-data/
> [error] Packet size (18446744073709551615 bits) is larger than remaining file size (262144 bits).
> [error] Stream index creation error.
> [error] Open file stream error.
> [warning] [Context] Cannot open_trace of format ctf at path ./ctf-data.
> [warning] [Context] cannot open trace "./ctf-data" from ./ctf-data/ for reading.
> [error] Cannot open any trace for reading.
> 
> [error] opening trace "./ctf-data/" for reading.
> 
> [error] none of the specified trace paths could be opened.
> 
> [acme@ssdandy linux]$
> 
> It stops working.
> 
> [acme@ssdandy linux]$ ls -la ctf-data/
> total 44
> drwxrwx---.  2 acme acme    41 Fev 25 16:12 .
> drwxrwxr-x. 28 acme acme  4096 Fev 25 16:19 ..
> -rw-rw----.  1 acme acme  4666 Fev 25 16:21 metadata
> -rw-rw----.  1 acme acme 32768 Fev 25 16:21 perf_stream_0
> [acme@ssdandy linux]$
> 
> Can you try to reproduce this? The ctf-data/metadata file is below:

hum, i just tried and can't reproduce this one.. anychance of mixed
babeltrace installations? How did you install babeltrace sources?

I assume this was some standard Fedora latest something system right?

jirka


git HEAD:

[root@krava perf]# git log --oneline | head -3
9534f89 perf data: Add tracepoint events fields CTF conversion support
bb848d1 perf stat: Report unsupported events properly
ffdfa43 perf tools: Compare JOBS to 0 after grep

test:

[root@krava perf]# LD_LIBRARY_PATH=/opt/libbabeltrace/lib/ ./perf trace record usleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.023 MB perf.data (88 samples) ]
[root@krava perf]# LD_LIBRARY_PATH=/opt/libbabeltrace/lib/ ./perf data convert --to-ctf=./ctf-data
[ perf data convert: Converted 'perf.data' into CTF data './ctf-data' ]
[ perf data convert: Converted and wrote 0.009 MB (88 samples) ]
[root@krava perf]# babeltrace ./ctf-data/
[10:04:03.320544407] (+?.?????????) raw_syscalls:sys_exit: { }, { perf_ip = 0xFFFFFFFF810235AC, perf_tid = 23899, perf_pid = 23899, perf_id = 82, perf_cpu = 3, perf_period = 1, common_type = 75, common_flags = 0, common_preempt_count = 0, common_pid = 23899, id = 59, ret = 0 }
[10:04:03.320568054] (+0.000023647) raw_syscalls:sys_enter: { }, { perf_ip = 0xFFFFFFFF81023420, perf_tid = 23899, perf_pid = 23899, perf_id = 78, perf_cpu = 3, perf_period = 1, common_type = 76, common_flags = 0, common_preempt_count = 0, common_pid = 23899, id = 12, args = [ [0] = 0x0, [1] = 0x0, [2] = 0x0, [3] = 0x0, [4] = 0x37F, [5] = 0x64 ] }
[10:04:03.320568993] (+0.000000939) raw_syscalls:sys_exit: { }, { perf_ip = 0xFFFFFFFF810235AC, perf_tid = 23899, perf_pid = 23899, perf_id = 82, perf_cpu = 3, perf_period = 1, common_type = 75, common_flags = 0, common_preempt_count = 0, common_pid = 23899, id = 12, ret = 24440832 }
...