Hi,
Am 22.12.2015 um 10:21 schrieb H. Nikolaus Schaller hns@goldelico.com:
Am 22.12.2015 um 10:16 schrieb H. Nikolaus Schaller hns@goldelico.com:
Hi,
Am 22.12.2015 um 00:14 schrieb Grazvydas Ignotas notaz@openpandora.org:
Hi,
I'm not sure but it looks like something is keeping some rcu lock for too long or using it's API wrong, which was noticed while that i2c thread was running. It looks like the relevant backtrace has failed (the one with __schedule) so it's unclear what's going on. I'd guess it's not necessary a problem with i2c.
I have found a good article on RCU:
https://lwn.net/Articles/262464/
and from that it appears that it is a deep mechanism for synchronizing linked list management, especially on out-of-order execution CPUs and SMP.
There is one critical and locking + work-queue-list related thing I do and with i2c4. It is that the new RGB LED driver is sitting on that bus and I have enabled MMC activity triggers for it:
http://git.goldelico.com/?p=gta04-kernel.git;a=blob;f=drivers/leds/leds-is31... http://git.goldelico.com/?p=gta04-kernel.git;a=blob;f=arch/arm/boot/dts/pyra...
But I am not using RCU explicitly anywhere and the LED driver follows the pca95xx and tca6507 principles (set_backlight can be called in interrupt context so it has to schedule a worker that really updates the chip through I2C commands).
So too much CPU activity might overload the driver or whatever, although I think my driver should be immune (it should start a new worker only if the old one is done).
Well, shortly after writing this mail I think I may not have locked activities well enough. Therefore a very fast led trigger could schedule more and more workers which are finally limited by the I2C bandwidth and then, the system is no longer capable of handling all incoming led trigger requests.
I will try to fix that situation.
Well, it depends on something I could not find good information about:
can a work function be called concurrently several times? Or is it guaranteed that a work function is scheduled from a work_queue only if the previous one is finished? In the latter case, the problem I was thinking about can not happen.
BR, Nikolaus
And if I remember corretctly the LEDs did stop blinking after that INFO message (which repeated itself every ~60 seconds).
We will see if such problems repeat.
BR, Nikolaus
On 12/21/2015 11:12 PM, H. Nikolaus Schaller wrote:
Hi Notaz, I am trying to bring up and test the new CPU boards and came across this log message:
[ 857.205142] INFO: rcu_sched self-detected stall on CPU [ 857.210537] 0-...: (80382 ticks this GP) idle=9b5/140000000000001/0 softirq=2813/2816 fqs=80324 [ 857.215154] INFO: rcu_sched detected stalls on CPUs/tasks: [ 857.215164] 0-...: (80382 ticks this GP) idle=9b5/140000000000001/0 softirq=2813/2816 fqs=80324 [ 857.215172] (detected by 1, t=80652 jiffies, g=117, c=116, q=4927) [ 857.215177] Task dump for CPU 0: [ 857.215187] irq/300-4807a00 R running 0 782 2 0x00000002 [ 857.215197] [<c05c0600>] (__schedule) from [<ee41ea00>] (0xee41ea00) [ 857.258091] (t=80656 jiffies g=117 c=116 q=4927) [ 857.263111] Task dump for CPU 0: [ 857.266489] irq/300-4807a00 R running 0 782 2 0x00000002 [ 857.273159] [<c0016290>] (unwind_backtrace) from [<c0012bc8>] (show_stack+0x10/0x14) [ 857.281273] [<c0012bc8>] (show_stack) from [<c0098370>] (rcu_dump_cpu_stacks+0x58/0x98) [ 857.289654] [<c0098370>] (rcu_dump_cpu_stacks) from [<c0098470>] (print_cpu_stall+0xc0/0x140) [ 857.298575] [<c0098470>] (print_cpu_stall) from [<c0099004>] (__rcu_pending+0x20/0x18c) [ 857.306957] [<c0099004>] (__rcu_pending) from [<c009bad8>] (rcu_check_callbacks+0x13c/0x1e0) [ 857.315797] [<c009bad8>] (rcu_check_callbacks) from [<c00a0568>] (update_process_times+0x30/0x5c) [ 857.325089] [<c00a0568>] (update_process_times) from [<c00b002c>] (tick_sched_handle+0x48/0x54) [ 857.334204] [<c00b002c>] (tick_sched_handle) from [<c00b0138>] (tick_sched_timer+0x58/0x9c) [ 857.342947] [<c00b0138>] (tick_sched_timer) from [<c00a1050>] (__run_hrtimer+0x164/0x264) [ 857.351528] [<c00a1050>] (__run_hrtimer) from [<c00a11c0>] (__hrtimer_run_queues+0x70/0x94) [ 857.360268] [<c00a11c0>] (__hrtimer_run_queues) from [<c00a18c4>] (hrtimer_interrupt+0xe4/0x248) [ 857.369468] [<c00a18c4>] (hrtimer_interrupt) from [<c0492b4c>] (arch_timer_handler_virt+0x2c/0x34) [ 857.378851] [<c0492b4c>] (arch_timer_handler_virt) from [<c0092740>] (handle_percpu_devid_irq+0xd8/0x160) [ 857.388871] [<c0092740>] (handle_percpu_devid_irq) from [<c008ea64>] (generic_handle_irq+0x18/0x28) [ 857.398348] [<c008ea64>] (generic_handle_irq) from [<c008eb9c>] (__handle_domain_irq+0x94/0xd8) [ 857.407458] [<c008eb9c>] (__handle_domain_irq) from [<c00094e0>] (gic_handle_irq+0x50/0x88) [ 857.416218] [<c00094e0>] (gic_handle_irq) from [<c05c58f8>] (__irq_svc+0x58/0x78) [ 857.424051] Exception stack(0xee333e80 to 0xee333ec8) [ 857.429341] 3e80: 00000001 00000004 00000000 ee646340 ee2ce760 ee2ce760 ee41ea00 ee2ce710 [ 857.437910] 3ea0: 00000000 00000000 c09534ee 00000001 00000001 ee333ed0 c008560c c05c53e4 [ 857.446466] 3ec0: 20010013 ffffffff [ 857.450129] [<c05c58f8>] (__irq_svc) from [<c05c53e4>] (_raw_spin_unlock_irq+0x28/0x2c) [ 857.458512] [<c05c53e4>] (_raw_spin_unlock_irq) from [<c0090370>] (irq_finalize_oneshot.part.3+0xb8/0xd4) [ 857.468533] [<c0090370>] (irq_finalize_oneshot.part.3) from [<c0090490>] (irq_thread_fn+0x2c/0x34) [ 857.477922] [<c0090490>] (irq_thread_fn) from [<c0090160>] (irq_thread+0x98/0x1f0) [ 857.485857] [<c0090160>] (irq_thread) from [<c00590fc>] (kthread+0xd4/0xe8) [ 857.493147] [<c00590fc>] (kthread) from [<c000efd0>] (ret_from_fork+0x14/0x24)
It looks like it is related to irq/300-4807a00 which would be the I2C4 module (assuming that there is a missing 0 at the end of 4807a00).
What else could I read from that?
BR, Nikolaus
Kernel mailing list Kernel@pyra-handheld.com http://pyra-handheld.com/cgi-bin/mailman/listinfo/kernel
Kernel mailing list Kernel@pyra-handheld.com http://pyra-handheld.com/cgi-bin/mailman/listinfo/kernel