Hey all,
I'll give two presentations on LTTng in the coming months, at Qt World Summit
and then at ESE Kongress. For demo purposes I setup a yocto build on an older
NXP IMX.6 board I had flying around in the office. I stumbled upon an
unexpected trace point order issue with lttng-ust:
These are the versions for the various LTTng related tools:
```
sources/poky/meta/recipes-kernel/lttng$ ls
babeltrace_1.5.3.bb lttng-modules lttng-modules_2.10.5.bb lttng-tools
lttng-tools_2.9.5.bb lttng-ust lttng-ust_2.10.1.bb
```
Everything works like a charm, except for a surprising side-effect when
recording LTTng-UST trace points. I have never seen the following two issues
before on my x86-64 host:
1) The syscalls done by lttng-ust internally seem to be recorded, which is not
desirable for me - I would prefer to only record the syscalls actually done by
the user application itself, not by lttng-ust. Is there a way to do that?
2) Oddly enough, the clock_gettime syscall is improperly nested with the ust
syscall, i.e. the order observed for all ust trace events is:
syscall_entry_getcpu
syscall_exit_getcpu
syscall_entry_clock_gettime
ust_event
syscall_exit_clock_gettime
This cannot be correct. Has anyone ever seen that? How can I resolve this -
does anyone know? Here's an excerpt from babeltrace (v1.5.6 on my host):
```
[09:36:23.999290417] (+0.000320667) imx6qsabresd syscall_entry_getcpu: {
cpu_id = 3 }, { tcache = 0x0 }
[09:36:23.999297084] (+0.06667) imx6qsabresd syscall_exit_getcpu: { cpu_id
= 3 }, { ret = 0, cpup = 0x7EA3B8FC, nodep = 0x0, tcache = 0x0 }
[09:36:23.999305084] (+0.08000) imx6qsabresd syscall_entry_clock_gettime:
{ cpu_id = 3 }, { which_clock = 1 }
[09:36:23.999308084] (+0.03000) imx6qsabresd qtcore:QObject_ctor: { cpu_id
= 3 }, { object = 0x7EA3BC84 }
[09:36:23.999311417] (+0.0) imx6qsabresd syscall_exit_clock_gettime: {
cpu_id = 3 }, { ret = 0, tp = 2124659000 }
[09:36:23.999341084] (+0.29667) imx6qsabresd syscall_entry_getcpu: {
cpu_id = 3 }, { tcache = 0x0 }
[09:36:23.999345417] (+0.04333) imx6qsabresd syscall_exit_getcpu: { cpu_id
= 3 }, { ret = 0, cpup = 0x7EA3B88C, nodep = 0x0, tcache = 0x0 }
[09:36:23.999350417] (+0.05000) imx6qsabresd syscall_entry_clock_gettime:
{ cpu_id = 3 }, { which_clock = 1 }
[09:36:23.999352417] (+0.02000) imx6qsabresd
qtgui:QGuiApplicationPrivate_init_entry: { cpu_id = 3 }, { }
[09:36:23.999355084] (+0.02667) imx6qsabresd syscall_exit_clock_gettime: {
cpu_id = 3 }, { ret = 0, tp = 212465 }
[09:36:23.999376417] (+0.21333) imx6qsabresd syscall_entry_getcpu: {
cpu_id = 3 }, { tcache = 0x0 }
[09:36:23.999380417] (+0.04000) imx6qsabresd syscall_exit_getcpu: { cpu_id
= 3 }, { ret = 0, cpup = 0x7EA3B844, nodep = 0x0, tcache = 0x0 }
[09:36:23.999385084] (+0.04667) imx6qsabresd syscall_entry_clock_gettime:
{ cpu_id = 3 }, { which_clock = 1 }
[09:36:23.999387084] (+0.02000) imx6qsabresd
qtcore:QCoreApplicationPrivate_init_entry: { cpu_id = 3 }, { }
[09:36:23.999389084] (+0.02000) imx6qsabresd syscall_exit_clock_gettime: {
cpu_id = 3 }, { ret = 0, tp = 2124658816 }
```
Here's how I configure the LTTng session:
```
#!/bin/sh
if [ ! -d /tmp/lttng ]; then
mkdir /tmp/lttng
fi
lttng create -o /tmp/lttng/$(date -Iseconds)
lttng enable-channel kernel -k
kernel_events=(
"sched_switch,sched_process_*"
"lttng_statedump_*"
kmem_{mm_page,cache}_{alloc,free}
power_cpu_frequency
block_rq_{issue,complete,requeue}
"irq_*"
"signal_*"
"workqueue_*"
)
for event in "${kernel_events[@]}"; do
lttng enable-event -c kernel -k "$event"
done
lttng enable-event -c kernel -k --syscall -a
lttng enable-channel ust -u
lttng enable-event -c ust -u -a
lttng start
```
Any help would be appreciated
--
Milian Wolff | milian.wo...@kdab.com | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts
smime.p7s
Description: S/MIME cryptographic signature
___
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
