* [ltt-dev] LTTng and Timestamps mismatch @ 2011-11-21 19:45 Abhishek Karoliya 2011-11-22 11:50 ` Mathieu Desnoyers 0 siblings, 1 reply; 4+ messages in thread From: Abhishek Karoliya @ 2011-11-21 19:45 UTC (permalink / raw) 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 ^ permalink raw reply [flat|nested] 4+ messages in thread
* [ltt-dev] LTTng and Timestamps mismatch 2011-11-21 19:45 [ltt-dev] LTTng and Timestamps mismatch Abhishek Karoliya @ 2011-11-22 11:50 ` Mathieu Desnoyers 2011-11-23 17:53 ` Abhishek Karoliya 0 siblings, 1 reply; 4+ messages in thread From: Mathieu Desnoyers @ 2011-11-22 11:50 UTC (permalink / raw) * 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 ^ permalink raw reply [flat|nested] 4+ messages in thread
* [ltt-dev] LTTng and Timestamps mismatch 2011-11-22 11:50 ` Mathieu Desnoyers @ 2011-11-23 17:53 ` Abhishek Karoliya 2011-11-23 18:16 ` Brosseau, Yannick 0 siblings, 1 reply; 4+ messages in thread From: Abhishek Karoliya @ 2011-11-23 17:53 UTC (permalink / raw) 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 > ^ permalink raw reply [flat|nested] 4+ messages in thread
* [ltt-dev] LTTng and Timestamps mismatch 2011-11-23 17:53 ` Abhishek Karoliya @ 2011-11-23 18:16 ` Brosseau, Yannick 0 siblings, 0 replies; 4+ messages in thread From: Brosseau, Yannick @ 2011-11-23 18:16 UTC (permalink / raw) 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 ^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2011-11-23 18:16 UTC | newest] Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2011-11-21 19:45 [ltt-dev] LTTng and Timestamps mismatch Abhishek Karoliya 2011-11-22 11:50 ` Mathieu Desnoyers 2011-11-23 17:53 ` Abhishek Karoliya 2011-11-23 18:16 ` Brosseau, Yannick
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox