GSoC Project | Basic Support for Trace Compass

[Sebastian Huber]

On 16/07/2019 10:04, Ravindra Kumar Meena wrote:
>     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.

Yes, the values are there, but babeltrace cannot deduce the clock 
source. In the LTTNG it displays it like this:

[17:50:44.093076317] (+0.000002071)

-- 
Sebastian Huber, embedded brains GmbH

Address : Dornierstr. 4, D-82178 Puchheim, Germany
Phone   : +49 89 189 47 41-16
Fax     : +49 89 189 47 41-09
E-Mail  : sebastian.huber at embedded-brains.de
PGP     : Public key available on request.

Diese Nachricht ist keine geschäftliche Mitteilung im Sinne des EHUG.