[ltt-dev] LTTng and Timestamps mismatch

[ltt-dev] LTTng and Timestamps mismatch

[Abhishek Karoliya]

Hello People,

I am using LTTng to get around a scheduling and priority inheritance
problem that we are observing on our system (powerpc e500v2 dual core,
linux 2.6.34). However, I need map timestamps for events as seen in
Lttng trace, kernel and application (I am using TSC divided by time
base freq for application). I see that even though stop tracing
(lttctl -D ) at 601.xxxxxx (/var/log/kernel )
Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.695548] LTT: 284 events
written in channel metadata (cpu 1, index 0)
Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.710868] LTT: 40 events
written in channel module_state (cpu 1, index 0)
...............................................
Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.710978] LTT: 32 events
written in channel softirq_state (cpu 1, index 0)

When I look dump the trace using lttv, I can see events that are
timestamped upto 670.xxxxxxxx.

I am wondering if this is due some timing offset? If yes, how could I
match them?

My Setup
ltt-control-0.89-05122011
lttv-0.12.36-18112010
linux-2.6.32 with pre-empt RT patch

Any pointers will be greatly appreciated.

Thanks
Abhi

[ltt-dev] LTTng and Timestamps mismatch

[Mathieu Desnoyers]

* Abhishek Karoliya (abhikaro at gmail.com) wrote:
> Hello People,
> 
> I am using LTTng to get around a scheduling and priority inheritance
> problem that we are observing on our system (powerpc e500v2 dual core,
> linux 2.6.34). However, I need map timestamps for events as seen in
> Lttng trace, kernel and application (I am using TSC divided by time
> base freq for application). I see that even though stop tracing
> (lttctl -D ) at 601.xxxxxx (/var/log/kernel )
> Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.695548] LTT: 284 events
> written in channel metadata (cpu 1, index 0)
> Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.710868] LTT: 40 events
> written in channel module_state (cpu 1, index 0)
> ...............................................
> Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.710978] LTT: 32 events
> written in channel softirq_state (cpu 1, index 0)
> 
> When I look dump the trace using lttv, I can see events that are
> timestamped upto 670.xxxxxxxx.
> 
> I am wondering if this is due some timing offset? If yes, how could I
> match them?
> 
> My Setup
> ltt-control-0.89-05122011
> lttv-0.12.36-18112010
> linux-2.6.32 with pre-empt RT patch
> 
> Any pointers will be greatly appreciated.

The LTTng timestamps, on powerpc, are directly derived from the TB
register value, without offset. The timestamp used in printk logs is
based, if my memory serves me correctly, on the kernel monotonic clock.
You might want to check what offset they apply to this clock, or try to
record the data from userspace through the marker_event (was theat even
the exact name, not sure anymore) debugfs file exposed by lttng through
debugfs. It's also possible that the printk timestamps are based on the
current time of day, which is offset by the ntp-correction.

Or you can try lttng 2.0. It comes with kernel and user-level tracing.
For the moment, it uses the CLOCK_MONOTONIC clock source both both
kernel and user-level tracing (until we reimplement the trace clocks
into lttng 2.0 and the vDSOs for userspace LTTng-UST). We also have the
dynamic task priority and nice level that we can record along with
events (see lttng add-context), which will be tremendously useful to
debug the kind of priority inversion problem you are investigating.

However, you need a kernel version >= 2.6.35 to build the lttng-modules.
No kernel patches are required (it's just a module package).

For more info, see http://lttng.org/lttng2.0

Best regards,

Mathieu


> 
> Thanks
> Abhi
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com

[ltt-dev] LTTng and Timestamps mismatch

[Abhishek Karoliya]

Thanks Mathieu for the pointers...

I have got a half cooked third party kernel when it comes to lttng
patches which is making it harder than it has to get to the code. The
kernel has been applied with Lttng patches but no one knows which
version of the patch reside. Off target but it will be immense help is
you or anyone could give help me deduce what kernel patch version has
been applied. What files or strings I could search? It is a 2.6.34
kernel with pre-empt rt patch.

I am all for 2.0 but the program here hasn't progressed to 2.6.35 and
it will be some time before we will start using it.

On Tue, Nov 22, 2011 at 11:50 AM, Mathieu Desnoyers
<compudj at krystal.dyndns.org> wrote:
> * Abhishek Karoliya (abhikaro at gmail.com) wrote:
>> Hello People,
>>
>> I am using LTTng to get around a scheduling and priority inheritance
>> problem that we are observing on our system (powerpc e500v2 dual core,
>> linux 2.6.34). However, I need map timestamps for events as seen in
>> Lttng trace, kernel and application (I am using TSC divided by time
>> base freq for application). I see that even though stop tracing
>> (lttctl -D ) at 601.xxxxxx (/var/log/kernel )
>> Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.695548] LTT: 284 events
>> written in channel metadata (cpu 1, index 0)
>> Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.710868] LTT: 40 events
>> written in channel module_state (cpu 1, index 0)
>> ...............................................
>> Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.710978] LTT: 32 events
>> written in channel softirq_state (cpu 1, index 0)
>>
>> When I look dump the trace using lttv, I can see events that are
>> timestamped upto 670.xxxxxxxx.
>>
>> I am wondering if this is due some timing offset? If yes, how could I
>> match them?
>>
>> My Setup
>> ltt-control-0.89-05122011
>> lttv-0.12.36-18112010
>> linux-2.6.32 with pre-empt RT patch
>>
>> Any pointers will be greatly appreciated.
>
> The LTTng timestamps, on powerpc, are directly derived from the TB
> register value, without offset. The timestamp used in printk logs is
> based, if my memory serves me correctly, on the kernel monotonic clock.
> You might want to check what offset they apply to this clock, or try to
> record the data from userspace through the marker_event (was theat even
> the exact name, not sure anymore) debugfs file exposed by lttng through
> debugfs. It's also possible that the printk timestamps are based on the
> current time of day, which is offset by the ntp-correction.
>
> Or you can try lttng 2.0. It comes with kernel and user-level tracing.
> For the moment, it uses the CLOCK_MONOTONIC clock source both both
> kernel and user-level tracing (until we reimplement the trace clocks
> into lttng 2.0 and the vDSOs for userspace LTTng-UST). We also have the
> dynamic task priority and nice level that we can record along with
> events (see lttng add-context), which will be tremendously useful to
> debug the kind of priority inversion problem you are investigating.
>
> However, you need a kernel version >= 2.6.35 to build the lttng-modules.
> No kernel patches are required (it's just a module package).
>
> For more info, see http://lttng.org/lttng2.0
>
> Best regards,
>
> Mathieu
>
>
>>
>> Thanks
>> Abhi
>>
>> _______________________________________________
>> ltt-dev mailing list
>> ltt-dev at lists.casi.polymtl.ca
>> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
>>
>
> --
> Mathieu Desnoyers
> Operating System Efficiency R&D Consultant
> EfficiOS Inc.
> http://www.efficios.com
>

[ltt-dev] LTTng and Timestamps mismatch

[Brosseau, Yannick]

I've have some patch to make LTTng 2.0 works on a 2.6.32 kernel. I'll
post that soon...

On Wed, Nov 23, 2011 at 12:53 PM, Abhishek Karoliya <abhikaro at gmail.com> wrote:
> Thanks Mathieu for the pointers...
>
> I have got a half cooked third party kernel when it comes to lttng
> patches which is making it harder than it has to get to the code. The
> kernel has been applied with Lttng patches but no one knows which
> version of the patch reside. Off target but it will be immense help is
> you or anyone could give help me deduce what kernel patch version has
> been applied. What files or strings I could search? It is a 2.6.34
> kernel with pre-empt rt patch.
>
> I am all for 2.0 but the program here hasn't progressed to 2.6.35 and
> it will be some time before we will start using it.
>
> On Tue, Nov 22, 2011 at 11:50 AM, Mathieu Desnoyers
> <compudj at krystal.dyndns.org> wrote:
>> * Abhishek Karoliya (abhikaro at gmail.com) wrote:
>>> Hello People,
>>>
>>> I am using LTTng to get around a scheduling and priority inheritance
>>> problem that we are observing on our system (powerpc e500v2 dual core,
>>> linux 2.6.34). However, I need map timestamps for events as seen in
>>> Lttng trace, kernel and application (I am using TSC divided by time
>>> base freq for application). I see that even though stop tracing
>>> (lttctl -D ) at 601.xxxxxx (/var/log/kernel )
>>> Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.695548] LTT: 284 events
>>> written in channel metadata (cpu 1, index 0)
>>> Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.710868] LTT: 40 events
>>> written in channel module_state (cpu 1, index 0)
>>> ...............................................
>>> Nov 21 16:26:13 XRX9C93E4059FFD kernel: [ ?601.710978] LTT: 32 events
>>> written in channel softirq_state (cpu 1, index 0)
>>>
>>> When I look dump the trace using lttv, I can see events that are
>>> timestamped upto 670.xxxxxxxx.
>>>
>>> I am wondering if this is due some timing offset? If yes, how could I
>>> match them?
>>>
>>> My Setup
>>> ltt-control-0.89-05122011
>>> lttv-0.12.36-18112010
>>> linux-2.6.32 with pre-empt RT patch
>>>
>>> Any pointers will be greatly appreciated.
>>
>> The LTTng timestamps, on powerpc, are directly derived from the TB
>> register value, without offset. The timestamp used in printk logs is
>> based, if my memory serves me correctly, on the kernel monotonic clock.
>> You might want to check what offset they apply to this clock, or try to
>> record the data from userspace through the marker_event (was theat even
>> the exact name, not sure anymore) debugfs file exposed by lttng through
>> debugfs. It's also possible that the printk timestamps are based on the
>> current time of day, which is offset by the ntp-correction.
>>
>> Or you can try lttng 2.0. It comes with kernel and user-level tracing.
>> For the moment, it uses the CLOCK_MONOTONIC clock source both both
>> kernel and user-level tracing (until we reimplement the trace clocks
>> into lttng 2.0 and the vDSOs for userspace LTTng-UST). We also have the
>> dynamic task priority and nice level that we can record along with
>> events (see lttng add-context), which will be tremendously useful to
>> debug the kind of priority inversion problem you are investigating.
>>
>> However, you need a kernel version >= 2.6.35 to build the lttng-modules.
>> No kernel patches are required (it's just a module package).
>>
>> For more info, see http://lttng.org/lttng2.0
>>
>> Best regards,
>>
>> Mathieu
>>
>>
>>>
>>> Thanks
>>> Abhi
>>>
>>> _______________________________________________
>>> ltt-dev mailing list
>>> ltt-dev at lists.casi.polymtl.ca
>>> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
>>>
>>
>> --
>> Mathieu Desnoyers
>> Operating System Efficiency R&D Consultant
>> EfficiOS Inc.
>> http://www.efficios.com
>>
>
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
>



-- 
Yannick Brosseau
www.projetmontreal.org
Consultant en logiciel libre
yannickbrosseau.com