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.
****************************************************************************************
_______________________________________________
ltt-dev mailing list
[email protected]
http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
