[lttng-dev] hiding lttng-ust-internal syscalls from record?

[Milian Wolff]

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.000006667) imx6qsabresd syscall_exit_getcpu: { cpu_id 
= 3 }, { ret = 0, cpup = 0x7EA3B8FC, nodep = 0x0, tcache = 0x0 }
[09:36:23.999305084] (+0.000008000) imx6qsabresd syscall_entry_clock_gettime: 
{ cpu_id = 3 }, { which_clock = 1 }
[09:36:23.999308084] (+0.000003000) imx6qsabresd qtcore:QObject_ctor: { cpu_id 
= 3 }, { object = 0x7EA3BC84 }
[09:36:23.999311417] (+0.000003333) imx6qsabresd syscall_exit_clock_gettime: { 
cpu_id = 3 }, { ret = 0, tp = 2124659000 }
[09:36:23.999341084] (+0.000029667) imx6qsabresd syscall_entry_getcpu: { 
cpu_id = 3 }, { tcache = 0x0 }
[09:36:23.999345417] (+0.000004333) imx6qsabresd syscall_exit_getcpu: { cpu_id 
= 3 }, { ret = 0, cpup = 0x7EA3B88C, nodep = 0x0, tcache = 0x0 }
[09:36:23.999350417] (+0.000005000) imx6qsabresd syscall_entry_clock_gettime: 
{ cpu_id = 3 }, { which_clock = 1 }
[09:36:23.999352417] (+0.000002000) imx6qsabresd 
qtgui:QGuiApplicationPrivate_init_entry: { cpu_id = 3 }, { }
[09:36:23.999355084] (+0.000002667) imx6qsabresd syscall_exit_clock_gettime: { 
cpu_id = 3 }, { ret = 0, tp = 2124658888 }
[09:36:23.999376417] (+0.000021333) imx6qsabresd syscall_entry_getcpu: { 
cpu_id = 3 }, { tcache = 0x0 }
[09:36:23.999380417] (+0.000004000) imx6qsabresd syscall_exit_getcpu: { cpu_id 
= 3 }, { ret = 0, cpup = 0x7EA3B844, nodep = 0x0, tcache = 0x0 }
[09:36:23.999385084] (+0.000004667) imx6qsabresd syscall_entry_clock_gettime: 
{ cpu_id = 3 }, { which_clock = 1 }
[09:36:23.999387084] (+0.000002000) imx6qsabresd 
qtcore:QCoreApplicationPrivate_init_entry: { cpu_id = 3 }, { }
[09:36:23.999389084] (+0.000002000) 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.wolff at kdab.com | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 3826 bytes
Desc: not available
URL: <https://lists.lttng.org/pipermail/lttng-dev/attachments/20191012/010ceae9/attachment.bin>