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

From: Arnaldo Carvalho de Melo
Date: Mon Mar 02 2015 - 10:32:53 EST


Em Sun, Mar 01, 2015 at 02:20:43PM +0100, Jiri Olsa escreveu:
> 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@xxxxxxxxxxxxx>
> > > 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 will recheck

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

This was on RHEL7

> 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 }
> ...
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/