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

[Piepho, Trent A]

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.

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. ****************************************************************************************