[lttng-dev] timestamp inconsistence between ‘lttng view’ and 'kernel log'

[lttng-dev] timestamp inconsistence between ‘lttng view’ and 'kernel log'

[Muni Sekhar]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain, Size: 905 bytes --]

 [ Please keep me in CC as I'm not subscribed to the list]


Hello,

First time I am using lttng to trace the kernel events.

I noticed the timestamp inconsistence between ‘lttng view’  and 'kernel log'.

Can it be possible to have the kernel log timestamp in lttng log?



Few lines of “lttng view” log is mentioned below:

[15:27:30.632837075] (+0.000002514) testbox  syscall_entry_open: {
cpu_id = 1 }, { filename = "/home/muni/v2.4/tests/debugtrans.so",
flags = 0, mode = 438 }

[15:27:30.632842383] (+0.000002235) testbox  syscall_entry_open: {
cpu_id = 1 }, { filename =
"/home/muni/v2.4/tests/debugtransmodule.so", flags = 0, mode = 438 }




Corresponding Kernel log is mentioned below:

Aug  3 15:27:30 testbox  kernel: [15117.050326] Entry debug_open

Aug  3 15:27:30 testbox  kernel: [15117.050326]

Aug  3 15:27:30 testbox  kernel: [15117.050333] Exit debug_open


-- 
Thanks,
Sekhar

[lttng-dev] timestamp inconsistence between ‘lttng view’ and 'kernel log'

[Mathieu Desnoyers]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain, Size: 1892 bytes --]

----- On Aug 3, 2016, at 6:56 AM, Muni Sekhar munisekharrms at gmail.com wrote:

> [ Please keep me in CC as I'm not subscribed to the list]
> 
> 
> Hello,
> 
> First time I am using lttng to trace the kernel events.
> 
> I noticed the timestamp inconsistence between ‘lttng view’  and 'kernel log'.
> 
> Can it be possible to have the kernel log timestamp in lttng log?
> 
> 
> 
> Few lines of “lttng view” log is mentioned below:
> 
> [15:27:30.632837075] (+0.000002514) testbox  syscall_entry_open: {
> cpu_id = 1 }, { filename = "/home/muni/v2.4/tests/debugtrans.so",
> flags = 0, mode = 438 }
> 
> [15:27:30.632842383] (+0.000002235) testbox  syscall_entry_open: {
> cpu_id = 1 }, { filename =
> "/home/muni/v2.4/tests/debugtransmodule.so", flags = 0, mode = 438 }
> 
> 
> 
> 
> Corresponding Kernel log is mentioned below:
> 
> Aug  3 15:27:30 testbox  kernel: [15117.050326] Entry debug_open
> 
> Aug  3 15:27:30 testbox  kernel: [15117.050326]
> 
> Aug  3 15:27:30 testbox  kernel: [15117.050333] Exit debug_open
> 

There is a way, but it's not straightforward. Basically, the kernel
uses the scheduler clock (local_clock) in dmesg. LTTng uses the
monotonic clock (corrected for small rate variations), and offsets
it by the delta between realtime and monotonic clock at trace start.

The difference between the sched clock and the monotonic clock makes it
non-trivial to correlate the two.

One trick you can use is to enable the printk_console LTTng kernel event.
This way, you will see the dmesg console messages with their timestamps in
the lttng trace, allowing you to correlate the two.

Best regards,

Mathieu


> 
> --
> Thanks,
> Sekhar
> _______________________________________________
> lttng-dev mailing list
> lttng-dev at lists.lttng.org
> https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com