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

From: Arnaldo Carvalho de Melo <acme@redhat.com>
To: Jiri Olsa <jolsa@kernel.org>
Cc: linux-kernel@vger.kernel.org,
	Sebastian Andrzej Siewior <bigeasy@linutronix.de>,
	David Ahern <dsahern@gmail.com>,
	Frederic Weisbecker <fweisbec@gmail.com>,
	Jeremie Galarneau <jgalar@efficios.com>,
	Namhyung Kim <namhyung@gmail.com>,
	Paul Mackerras <paulus@samba.org>,
	Peter Zijlstra <peterz@infradead.org>,
	Tom Zanussi <tzanussi@gmail.com>, Wang Nan <wangnan0@huawei.com>
Subject: Re: [PATCH 05/11] perf data: Add tracepoint events fields CTF conversion support
Date: Wed, 25 Feb 2015 16:23:44 -0300	[thread overview]
Message-ID: <20150225192344.GH18705@kernel.org> (raw)
In-Reply-To: <1424470628-5969-6-git-send-email-jolsa@kernel.org>

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:

- Arnaldo

[acme@ssdandy linux]$ cat ctf-data/metadata 
/* CTF 1.8 */

trace {
	major = 1;
	minor = 8;
	uuid = "8b5ba0f6-f29f-4adc-bf12-1fc8e9afec5f";
	byte_order = le;
	packet.header := struct {
		integer { size = 32; align = 8; signed = false; encoding = none; base = decimal; byte_order = le; } magic;
		integer { size = 8; align = 8; signed = false; encoding = none; base = decimal; byte_order = le; } uuid[16];
		integer { size = 32; align = 8; signed = false; encoding = none; base = decimal; byte_order = le; } stream_id;
	} align(8);
};

env {
	host = "ssdandy.ghostprotocols.net";
	sysname = "Linux";
	release = "3.10.0-210.el7.x86_64";
	version = "3.19.rc7.gd15174";
	machine = "x86_64";
	domain = "kernel";
	tracer_name = "perf";
};

clock {
	name = perf_clock;
	uuid = "b2bfe13f-06ed-4ef6-a3cd-fb0f28c6c608";
	description = "perf clock";
	freq = 1000000000;
	precision = 10;
	offset_s = 0;
	offset = 0;
	absolute = FALSE;
};

stream {
	id = 0;
	event.header := struct {
		integer { size = 32; align = 8; signed = false; encoding = none; base = decimal; byte_order = le; } id;
		integer { size = 64; align = 8; signed = false; encoding = none; base = decimal; byte_order = le; map = clock.perf_clock.value; } timestamp;
	} align(8);

	packet.context := struct {
		integer { size = 64; align = 8; signed = false; encoding = none; base = decimal; byte_order = le; } timestamp_begin;
		integer { size = 64; align = 8; signed = false; encoding = none; base = decimal; byte_order = le; } timestamp_end;
		integer { size = 64; align = 8; signed = false; encoding = none; base = decimal; byte_order = le; } content_size;
		integer { size = 64; align = 8; signed = false; encoding = none; base = decimal; byte_order = le; } packet_size;
		integer { size = 64; align = 8; signed = false; encoding = none; base = decimal; byte_order = le; } events_discarded;
	} align(8);
};

event {
	name = "raw_syscalls:sys_enter";
	id = 0;
	stream_id = 0;
	fields := struct {
		integer { size = 64; align = 1; signed = false; encoding = none; base = hexadecimal; byte_order = le; } perf_ip;
		integer { size = 32; align = 1; signed = true; encoding = none; base = decimal; byte_order = le; } perf_tid;
		integer { size = 32; align = 1; signed = true; encoding = none; base = decimal; byte_order = le; } perf_pid;
		integer { size = 64; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } perf_id;
		integer { size = 32; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } perf_cpu;
		integer { size = 64; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } perf_period;
		integer { size = 32; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } common_type;
		integer { size = 32; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } common_flags;
		integer { size = 32; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } common_preempt_count;
		integer { size = 32; align = 1; signed = true; encoding = none; base = decimal; byte_order = le; } common_pid;
		integer { size = 64; align = 1; signed = true; encoding = none; base = decimal; byte_order = le; } id;
		string { encoding = UTF8; } args;
	} align(8);
};

event {
	name = "raw_syscalls:sys_exit";
	id = 1;
	stream_id = 0;
	fields := struct {
		integer { size = 64; align = 1; signed = false; encoding = none; base = hexadecimal; byte_order = le; } perf_ip;
		integer { size = 32; align = 1; signed = true; encoding = none; base = decimal; byte_order = le; } perf_tid;
		integer { size = 32; align = 1; signed = true; encoding = none; base = decimal; byte_order = le; } perf_pid;
		integer { size = 64; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } perf_id;
		integer { size = 32; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } perf_cpu;
		integer { size = 64; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } perf_period;
		integer { size = 32; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } common_type;
		integer { size = 32; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } common_flags;
		integer { size = 32; align = 1; signed = false; encoding = none; base = decimal; byte_order = le; } common_preempt_count;
		integer { size = 32; align = 1; signed = true; encoding = none; base = decimal; byte_order = le; } common_pid;
		integer { size = 64; align = 1; signed = true; encoding = none; base = decimal; byte_order = le; } id;
		integer { size = 64; align = 1; signed = true; encoding = none; base = decimal; byte_order = le; } ret;
	} align(1);
};

[acme@ssdandy linux]$