The clock definitions for the timestamps are not right. I loaded the
trace with Trace Compass and it shows always the same timestamp. For
example in
102-tracing-wget-critical-path/wget-first-call
I get this:
babeltrace . | grep sched | head
[17:50:44.093074246] (+?.?????????) arnaud-desktop sched_wakeup: {
cpu_id = 3 }, { comm = "lttng-consumerd", tid = 6854, prio = 20,
target_cpu = 0 }
[17:50:44.093076317] (+0.000002071) arnaud-desktop sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper/0", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "lttng-consumerd", next_tid = 6854,
next_prio = 20 }
[17:50:44.093115428] (+0.000017727) arnaud-desktop sched_wakeup: {
cpu_id = 0 }, { comm = "code", tid = 3906, prio = 20, target_cpu = 2 }
[17:50:44.093116515] (+0.000001087) arnaud-desktop sched_switch: {
cpu_id = 2 }, { prev_comm = "swapper/2", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "code", next_tid = 3906, next_prio = 20 }
[17:50:44.093167902] (+0.000002249) arnaud-desktop sched_switch: {
cpu_id = 0 }, { prev_comm = "lttng-consumerd", prev_tid = 6854,
prev_prio = 20, prev_state = 2, next_comm = "swapper/0", next_tid = 0,
next_prio = 20 }
[17:50:44.093256580] (+0.000003128) arnaud-desktop sched_wakeup: {
cpu_id = 2 }, { comm = "code", tid = 3915, prio = 20, target_cpu = 0 }
[17:50:44.093257484] (+0.000000267) arnaud-desktop sched_switch: {
cpu_id = 0 }, { prev_comm = "swapper/0", prev_tid = 0, prev_prio = 20,
prev_state = 0, next_comm = "code", next_tid = 3915, next_prio = 20 }
[17:50:44.093271009] (+0.000001250) arnaud-desktop sched_switch: {
cpu_id = 0 }, { prev_comm = "code", prev_tid = 3915, prev_prio = 20,
prev_state = 1, next_comm = "swapper/0", next_tid = 0, next_prio = 20 }
[17:50:44.093271610] (+0.000000601) arnaud-desktop sched_wakeup: {
cpu_id = 2 }, { comm = "code", tid = 3916, prio = 20, target_cpu = 2 }
[17:50:44.093272936] (+0.000000887) arnaud-desktop sched_switch: {
cpu_id = 2 }, { prev_comm = "code", prev_tid = 3906, prev_prio = 20,
prev_state = 0, next_comm = "code", next_tid = 3916, next_prio = 20 }
In our trace output I get this:
babeltrace . | head
0 RTEMS_RECORDING_EVENT: { cpu_id = 17 }, { ns = 986422, events = (
"RTEMS_RECORD_THREAD_STACK_CURRENT" : container = 209 ), data = 7392 }
0 RTEMS_RECORDING_EVENT: { cpu_id = 17 }, { ns = 986422, events = (
"RTEMS_RECORD_THREAD_SWITCH_IN" : container = 215 ), data = 167837739 }
0 RTEMS_RECORDING_EVENT: { cpu_id = 17 }, { ns = 1006753, events = (
"RTEMS_RECORD_THREAD_SWITCH_OUT" : container = 216 ), data = 167837739 }
0 RTEMS_RECORDING_EVENT: { cpu_id = 17 }, { ns = 1006753, events = (
"RTEMS_RECORD_THREAD_STACK_CURRENT" : container = 209 ), data = 5856 }
0 RTEMS_RECORDING_EVENT: { cpu_id = 17 }, { ns = 1006753, events = (
"RTEMS_RECORD_THREAD_SWITCH_IN" : container = 215 ), data = 151060500 }
0 RTEMS_RECORDING_EVENT: { cpu_id = 17 }, { ns = 1044799, events = (
"RTEMS_RECORD_THREAD_SWITCH_OUT" : container = 216 ), data = 151060500 }
0 RTEMS_RECORDING_EVENT: { cpu_id = 17 }, { ns = 1044799, events = (
"RTEMS_RECORD_THREAD_STACK_CURRENT" : container = 209 ), data = 7392 }
0 RTEMS_RECORDING_EVENT: { cpu_id = 17 }, { ns = 1044799, events = (
"RTEMS_RECORD_THREAD_SWITCH_IN" : container = 215 ), data = 167837739 }
0 RTEMS_RECORDING_EVENT: { cpu_id = 17 }, { ns = 1064443, events = (
"RTEMS_RECORD_THREAD_SWITCH_OUT" : container = 216 ), data = 167837739 }
0 RTEMS_RECORDING_EVENT: { cpu_id = 17 }, { ns = 1064443, events = (
"RTEMS_RECORD_THREAD_STACK_CURRENT" : container = 209 ), data = 5856 }
I included both timestamps values in the binary stream file. Only the
timestamp value is not shown in our output. The timestamp values were
stored in nanoseconds.
