I'm trying to use lttng to analyse the scheduling on a remote system. However, displaying the trace as text format with babeltrace shows that all recorded events have the same timestamp. Consequently, the visualization in TraceCompass fails.
thomas@horrorshow: babeltrace ~/temp/lttng/my-trace/MySystem/my-session-20170608-133943/ | head
[13:41:59.444999936] (+?.?????????) MySystem sched_stat_runtime: { cpu_id = 0 }, { comm = "lttng-sessiond", tid = 1533, runtime = 5016120, vruntime = 451268995605 }
[13:41:59.444999936] (+0.000000000) MySystem sched_waking: { cpu_id = 0 }, { comm = "lttng-consumerd", tid = 1547, prio = 20, target_cpu = 0 }
[13:41:59.444999936] (+0.000000000) MySystem sched_stat_runtime: { cpu_id = 0 }, { comm = "lttng-sessiond", tid = 1533, runtime = 276632, vruntime = 451269272237 }
[13:41:59.444999936] (+0.000000000) MySystem sched_wakeup: { cpu_id = 0 }, { comm = "lttng-consumerd", tid = 1547, prio = 20, target_cpu = 0 }
[13:41:59.444999936] (+0.000000000) MySystem sched_switch: { cpu_id = 0 }, { prev_comm = "lttng-sessiond", prev_tid = 1533, prev_prio = 20, prev_state = 4096, next_comm = "lttng-consumerd", next_tid = 1547, next_prio = 20 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_exit_epoll_wait: { cpu_id = 0 }, { ret = 1, fds_length = 1, overflow = 0, fds = [ [0] = { data_union = { u64 = 0x1C, fd = 28 }, raw_events = 0x1, events = { EPOLLIN = 1, EPOLLPRI = 0, EPOLLOUT = 0, EPOLLERR = 0, padding = 0 } } ] }
[13:41:59.444999936] (+0.000000000) MySystem syscall_entry_ioctl: { cpu_id = 0 }, { fd = 28, cmd = 62981, arg = 1547 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_exit_ioctl: { cpu_id = 0 }, { ret = 0, arg = 1547 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_entry_ioctl: { cpu_id = 0 }, { fd = 28, cmd = 2147808776, arg = 3047156396 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_exit_ioctl: { cpu_id = 0 }, { ret = 0, arg = 3047156396 }
thomas@horrorshow: babeltrace ~/temp/lttng/my-trace/MySystem/my-session-20170608-133943/ | tail
[13:41:59.444999936] (+0.000000000) MySystem sched_wakeup: { cpu_id = 0 }, { comm = "rcu_preempt", tid = 7, prio = 20, target_cpu = 0 }
[13:41:59.444999936] (+0.000000000) MySystem sched_switch: { cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 1698, prev_prio = 20, prev_state = 4096, next_comm = "rcu_preempt", next_tid = 7, next_prio = 20 }
[13:41:59.444999936] (+0.000000000) MySystem sched_stat_runtime: { cpu_id = 0 }, { comm = "rcu_preempt", tid = 7, runtime = 128301, vruntime = 456917982563 }
[13:41:59.444999936] (+0.000000000) MySystem sched_switch: { cpu_id = 0 }, { prev_comm = "rcu_preempt", prev_tid = 7, prev_prio = 20, prev_state = 1, next_comm = "lttng", next_tid = 1698, next_prio = 20 }
[13:41:59.444999936] (+0.000000000) MySystem sched_waking: { cpu_id = 0 }, { comm = "lttng-sessiond", tid = 1533, prio = 20, target_cpu = 0 }
[13:41:59.444999936] (+0.000000000) MySystem sched_stat_runtime: { cpu_id = 0 }, { comm = "lttng", tid = 1698, runtime = 209068, vruntime = 456921063330 }
[13:41:59.444999936] (+0.000000000) MySystem sched_wakeup: { cpu_id = 0 }, { comm = "lttng-sessiond", tid = 1533, prio = 20, target_cpu = 0 }
[13:41:59.444999936] (+0.000000000) MySystem sched_switch: { cpu_id = 0 }, { prev_comm = "lttng", prev_tid = 1698, prev_prio = 20, prev_state = 4096, next_comm = "lttng-sessiond", next_tid = 1533, next_prio = 20 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_exit_recvmsg: { cpu_id = 0 }, { ret = 13156, msg = 3046107868 }
[13:41:59.444999936] (+0.000000000) MySystem syscall_entry_ioctl: { cpu_id = 0 }, { fd = 31, cmd = 63063, arg = 17 }
The trace as running for a few seconds and is 912K large.
I used the following commands to start the tracing on the embedded Linux device, using lttng-relayd to transfer the data to my host system for analysis:
lttng create my-session --set-url=net://10.0.28.1
lttng enable-channel --kernel --subbuf-size=2621440 channel0
lttng enable-event --kernel --syscall --all --channel channel0
lttng enable-event --kernel --channel channel0 sched*
lttng start
# Wait a bit
lttng stop
How can I fix the timestamps?
The folks at the lttng-dev mailing list solved the problem for me: I accidentally loaded the kernel module for a fake test clock, instead of the kernel module for the real clock.
My mistake was that I ran insmod on all .ko files provided by lttng manually. However, the proper way is to let lttng-sessiond load the modules automatically, which will ignore the fake test clock module. The automatic module loading failed for me because I didn't run depmod -a after installing the kernel modules.
After depmod -a, everything worked correctly, and the timestamps were correct.