[lttng-dev] Timestamps in babeltrace

[Gerlando Falauto]

Hi,

I am trying to use LLTng 2.0 (since I have no alternative for a 3.0 
kernel!) and I of course use babeltrace to read them.
Problem is, I can't make any sense out of the timestamps, as I get 
something like (two CPU-hog bash processes):

[1658841591493] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646, 
next_prio = 20 }
[1658845590645] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647, 
next_prio = 20 }
[1658849590039] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646, 
next_prio = 20 }
[1658853591069] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647, 
next_prio = 20 }
[1662152559395] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646, 
next_prio = 20 }
[1662156587941] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647, 
next_prio = 20 }
[1662160557698] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646, 
next_prio = 20 }
[1662164557517] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647, 
next_prio = 20 }
[....................................cut...........................]
[1663140553029] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647, 
next_prio = 20 }
[1663144555029] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646, 
next_prio = 20 }
[1663148552423] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
646, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 647, 
next_prio = 20 }
[1666447519719] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
647, prev_prio = 20, prev_state = 0, next_comm = "bash", next_tid = 646, 
next_prio = 20 }
[1666451561355] sched_switch: { 0 }, { prev_comm = "bash", prev_tid = 
646, prev_prio = 20, prev_state = 0, next_comm = "kworker/0:1", next_tid 
= 94, next_prio = 20 }
[1666451863719] sched_switch: { 0 }, { prev_comm = "kworker/0:1", 
prev_tid = 94, prev_prio = 20, prev_state = 1, next_comm = "bash", 
next_tid = 647, next_prio = 20 }

Which made me think timestamps were expressed in nanoseconds, as I am 
running this on 4ms-tick PowerPC (CONFIG_HZ=250), and the difference 
between timestamps is approximately 4,000,000.
However, I get these huge 3.3 second gaps between for instance between 
1658853591069 and 1662152559395.
Curiously enough, these leap 3.3 seconds occur exactly (well, within 4ms 
precision...) every second. Kind of like the "seconds" part of the 
timestamp is calculated on a wrong-base arithmetics or so....
This also makes sense as the seconds' portion of the timestamp is 
essentially 4.3 times bigger than the uptime (and any time stretch is 
4.3 times bigger than reality, for that matter).

Any suggestions?

Thanks!
Gerlando

P.S. This also happens without my hack for flight recording mode...