[ltt-dev] Help with problem (maybe) in LTTng on 2.6.37 on ARM

[Mathieu Desnoyers]

* Piepho, Trent A (Trent.A.Piepho at delphi.com) wrote:
> Did you ever figure out what was going on?  I think I'm have the same
> problem. I'm using lttng on a Freescale iMX53, also an ARM Cortex-A8
> processor.  The kernel version is 2.6.31, which is the newest kernel
> supported for the processor.  I seem to having the same problem.
> There aren't any bogus softirq ids, but the trace would seem to
> indicate the processor is spending 99% of the time running in soft irq
> mode.  I've set the kernel to 1000 Hz and the timer softirq takes
> almost 1 ms, i.e. virtually all the time until the next timer
> interrupt.  I bet you are using a 100 Hz kernel and thus see 10 ms
> between interrupts.

This behavior is a known side-effect of the asm-generic/trace-clock.h
trace clock support, which uses a time-related timer tick counter for
high bits, but uses an event count for the low bits, having no better
known time source to use. Therefore, all events appear to be squeezed
just after the timer tick. If you use ARM, I recommend you have a look
at the OMAP3 ccnt-register-based trace clock implementation (this might
be only available on newer kernels though) for better accuracy.

Thanks,

Mathieu


> 
> kernel.irq_entry: 0.084002929 (/home/user/traces/trace1/kernel_0), 0, 0, swapper, , 0, 0x0, IRQ { ip = 2147650048, handler = 0x80036dd4, irq_id = 39, kernel_mode = 1 }
> kernel.timer_update_time: 0.084003051 (/home/user/traces/trace1/kernel_0), 0, 0, swapper, , 0, 0x0, IRQ { jiffies = 4299386742, xtime_sec = 4719, xtime_nsec = 74001440, walltomonotonic_sec = 0, walltomonotonic_nsec = 0 }
> kernel.softirq_raise: 0.084003173 (/home/user/traces/trace1/kernel_0), 0, 0, swapper, , 0, 0x0, IRQ { softirq_id = 1 [run_timer_softirq+0x0/0x218] }
> kernel.irq_exit: 0.084003295 (/home/user/traces/trace1/kernel_0), 0, 0, swapper, , 0, 0x0, SYSCALL { handled = 1 }
> kernel.softirq_entry: 0.084003417 (/home/user/traces/trace1/kernel_0), 0, 0, swapper, , 0, 0x0, SOFTIRQ { softirq_id = 1 [run_timer_softirq+0x0/0x218] }
> 
> ** almost 1 ms passes **
> 
> kernel.timer_set: 0.085000122 (/home/user/traces/trace1/kernel_0), 0, 0, swapper, , 0, 0x0, SOFTIRQ { expires = 4419447, function = 0x8007c028, data = 0 }
> kernel.timer_set: 0.085000244 (/home/user/traces/trace1/kernel_0), 0, 0, swapper, , 0, 0x0, SOFTIRQ { expires = 4419447, function = 0x801843e0, data = 0 }
> kernel.softirq_exit: 0.085000366 (/home/user/traces/trace1/kernel_0), 0, 0, swapper, , 0, 0x0, SYSCALL { softirq_id = 1 [run_timer_softirq+0x0/0x218] }
> 
> Supposedly there are 122 ns between the end of the softirq and the next timer interrupt, which is about 97 clock cycles at 800 MHz.  That seems unlikely.
> 
> kernel.irq_entry: 0.085000488 (/home/user/traces/trace1/kernel_0), 0, 0, swapper, , 0, 0x0, IRQ { ip = 2147650048, handler = 0x80036dd4, irq_id = 39, kernel_mode = 1 }
> kernel.timer_update_time: 0.085000610 (/home/user/traces/trace1/kernel_0), 0, 0, swapper, , 0, 0x0, IRQ { jiffies = 4299386743, xtime_sec = 4719, xtime_nsec = 74001443, walltomonotonic_sec = 0, walltomonotonic_nsec = 0 }
> kernel.softirq_raise: 0.085000732 (/home/user/traces/trace1/kernel_0), 0, 0, swapper, , 0, 0x0, IRQ { softirq_id = 1 [run_timer_softirq+0x0/0x218] }
> 
> Basically every timer irq is like this.  It seems like it must be something with the trace clock being off.  Like the clock is incrementing in 1 ms ticks during the timer soft irq and the sub-ms granularity in the timer is wrong.  The events between irq_entry and softirq_entry should be moved forward almost 1 ms, so that the time between softirq_entry and timer_set is something in the microsecond range.
> **************************************************************************************** Note: If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient, you are hereby notified that any dissemination, distribution or copying of this communication is strictly prohibited. If you have received this communication in error, please notify us immediately by replying to the message and deleting it from your computer. Thank you. ****************************************************************************************
> 
> _______________________________________________
> 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