RCU Stall with QorIQ Linux SDK v2.0-1703

[eric_gaucher]

Hi,

We use QorIQ Linux SDK v2.0-1703 on a custom T1042 processing board. 

Our application stop working after a few hours (between 1 and 8 hours) which eventually locks/hangs the system..

In the kernel log we find many RCU stall.

dmesg
[ 12.989088] kobject: 'ttydneS36' (c00000007e153810): kobject_uevent_env
[ 12.989102] kobject: 'ttydneS36' (c00000007e153810): fill_kobj_path: path = '/devices/platform/ffe250000.pcie/pci0001:00/0001:00:00.0/0001:01:00.0/tty/ttydneS36'
[ 12.993286] 0001:01:00.0: ttydneS37 at MMIO 0x8000080088e20000 (irq = 0, base_baud = 230400) is a FpgaSerial
[ 13.002115] kobject: 'ttydneS37' (c00000007e157010): kobject_add_internal: parent: 'tty', set: 'devices'
[ 13.011915] kobject: 'ttydneS37' (c00000007e157010): kobject_uevent_env
[ 13.011931] kobject: 'ttydneS37' (c00000007e157010): fill_kobj_path: path = '/devices/platform/ffe250000.pcie/pci0001:00/0001:00:00.0/0001:01:00.0/tty/ttydneS37'
[ 13.015538] 0001:01:00.0: ttydneS38 at MMIO 0x8000080088e20000 (irq = 0, base_baud = 230400) is a FpgaSerial
[ 13.024402] kobject: 'ttydneS38' (c00000007c016010): kobject_add_internal: parent: 'tty', set: 'devices'
[ 13.036091] kobject: 'ttydneS38' (c00000007c016010): kobject_uevent_env
[ 13.036106] kobject: 'ttydneS38' (c00000007c016010): fill_kobj_path: path = '/devices/platform/ffe250000.pcie/pci0001:00/0001:00:00.0/0001:01:00.0/tty/ttydneS38'
[ 13.040667] 0001:01:00.0: ttydneS39 at MMIO 0x8000080088e20000 (irq = 0, base_baud = 230400) is a FpgaSerial
[ 13.049265] kobject: 'ttydneS39' (c00000007c67a010): kobject_add_internal: parent: 'tty', set: 'devices'
[ 13.059240] kobject: 'ttydneS39' (c00000007c67a010): kobject_uevent_env
[ 13.059378] kobject: 'ttydneS39' (c00000007c67a010): fill_kobj_path: path = '/devices/platform/ffe250000.pcie/pci0001:00/0001:00:00.0/0001:01:00.0/tty/ttydneS39'
[ 13.064973] 0001:01:00.0: ttydneS40 at MMIO 0x8000080088e20000 (irq = 0, base_baud = 230400) is a FpgaSerial
[ 13.075180] kobject: 'ttydneS40' (c00000007e156810): kobject_add_internal: parent: 'tty', set: 'devices'
[ 13.087438] kobject: 'ttydneS40' (c00000007e156810): kobject_uevent_env
[ 13.087455] kobject: 'ttydneS40' (c00000007e156810): fill_kobj_path: path = '/devices/platform/ffe250000.pcie/pci0001:00/0001:00:00.0/0001:01:00.0/tty/ttydneS40'
[ 13.090869] 0001:01:00.0: ttydneS41 at MMIO 0x8000080088e20000 (irq = 0, base_baud = 230400) is a FpgaSerial
[ 13.101065] kobject: 'ttydneS41' (c00000007e155810): kobject_add_internal: parent: 'tty', set: 'devices'
[ 13.110695] kobject: 'ttydneS41' (c00000007e155810): kobject_uevent_env
[ 13.110711] kobject: 'ttydneS41' (c00000007e155810): fill_kobj_path: path = '/devices/platform/ffe250000.pcie/pci0001:00/0001:00:00.0/0001:01:00.0/tty/ttydneS41'
[ 13.115763] kobject: 'drivers' (c0000000ed5eb340): kobject_add_internal: parent: 'fpgadriverdne', set: '<NULL>'
[ 13.118126] kobject: 'fpgadriverdne' (c0000000ee376b00): kobject_uevent_env
[ 13.118138] kobject: 'fpgadriverdne' (c0000000ee376b00): fill_kobj_path: path = '/bus/pci/drivers/fpgadriverdne'
[ 14.604424] jffs2: notice: (1716) check_node_data: wrong data CRC in data node at 0x1af55044: read 0x1f621e42, calculated 0x86de3c62.
[ 14.616701] jffs2: notice: (1716) check_node_data: wrong data CRC in data node at 0x1af53044: read 0x1f621e42, calculated 0x86de3c62.
[ 14.629702] jffs2: notice: (1716) check_node_data: wrong data CRC in data node at 0x22135578: read 0xfcdbc2b7, calculated 0xbb1fa648.
[ 15.723847] jffs2: notice: (1716) check_node_data: wrong data CRC in data node at 0x0c1caf78: read 0x3f41c8d6, calculated 0x7c7c3806.
[54184.140436] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54184.140443] (detected by 3, t=21002 jiffies, g=3148130, c=3148129, q=6300)
[54184.140447] All QSes seen, last rcu_preempt kthread activity 21002 (4348851482-4348830480), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54184.140453] swapper/3 R running task 0 0 1 0x00000800
[54184.140455] Call Trace:
[54184.140468] [c0000000f01174b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54184.140478] [c0000000f0117530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54184.140484] [c0000000f0117680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54184.140492] [c0000000f0117700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54184.140497] [c0000000f01177b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54184.140502] [c0000000f0117840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54184.140508] [c0000000f0117950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54184.140513] [c0000000f01179e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54184.140518] [c0000000f0117a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54184.140525] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54184.140533] [c0000000f0117d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54184.140542] [c0000000f0117de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54184.140549] [c0000000f0117ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54184.140553] [c0000000f0117f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54184.140556] rcu_preempt kthread starved for 21002 jiffies!
[54207.742414] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54207.742421] (detected by 3, t=21002 jiffies, g=3148605, c=3148604, q=6307)
[54207.742425] All QSes seen, last rcu_preempt kthread activity 21002 (4348875084-4348854082), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54207.742431] swapper/3 R running task 0 0 1 0x00000800
[54207.742432] Call Trace:
[54207.742446] [c0000000f01174b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54207.742455] [c0000000f0117530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54207.742461] [c0000000f0117680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54207.742469] [c0000000f0117700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54207.742474] [c0000000f01177b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54207.742478] [c0000000f0117840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54207.742485] [c0000000f0117950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54207.742490] [c0000000f01179e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54207.742495] [c0000000f0117a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54207.742502] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54207.742510] [c0000000f0117d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54207.742519] [c0000000f0117de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54207.742526] [c0000000f0117ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54207.742531] [c0000000f0117f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54207.742533] rcu_preempt kthread starved for 21002 jiffies!
[54233.401387] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54233.401394] (detected by 1, t=21002 jiffies, g=3149644, c=3149643, q=6302)
[54233.401398] All QSes seen, last rcu_preempt kthread activity 21002 (4348900743-4348879741), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54233.401404] swapper/1 R running task 0 0 1 0x00000800
[54233.401406] Call Trace:
[54233.401420] [c0000000f01074b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54233.401429] [c0000000f0107530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54233.401435] [c0000000f0107680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54233.401443] [c0000000f0107700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54233.401448] [c0000000f01077b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54233.401452] [c0000000f0107840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54233.401459] [c0000000f0107950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54233.401464] [c0000000f01079e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54233.401469] [c0000000f0107a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54233.401476] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54233.401484] [c0000000f0107d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54233.401493] [c0000000f0107de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54233.401500] [c0000000f0107ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54233.401504] [c0000000f0107f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54233.401507] rcu_preempt kthread starved for 21002 jiffies!
[54254.773366] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54254.773373] (detected by 1, t=21002 jiffies, g=3149730, c=3149729, q=6303)
[54254.773377] All QSes seen, last rcu_preempt kthread activity 21002 (4348922115-4348901113), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54254.773383] swapper/1 R running task 0 0 1 0x00000800
[54254.773384] Call Trace:
[54254.773398] [c0000000f01074b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54254.773408] [c0000000f0107530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54254.773414] [c0000000f0107680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54254.773422] [c0000000f0107700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54254.773427] [c0000000f01077b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54254.773432] [c0000000f0107840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54254.773439] [c0000000f0107950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54254.773443] [c0000000f01079e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54254.773448] [c0000000f0107a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54254.773456] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54254.773464] [c0000000f0107d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54254.773473] [c0000000f0107de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54254.773480] [c0000000f0107ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54254.773485] [c0000000f0107f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54254.773487] rcu_preempt kthread starved for 21002 jiffies!
[54276.764344] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54276.764351] (detected by 1, t=21002 jiffies, g=3149948, c=3149947, q=6303)
[54276.764354] All QSes seen, last rcu_preempt kthread activity 21002 (4348944106-4348923104), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54276.764360] swapper/1 R running task 0 0 1 0x00000800
[54276.764362] Call Trace:
[54276.764376] [c0000000f01074b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54276.764385] [c0000000f0107530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54276.764391] [c0000000f0107680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54276.764399] [c0000000f0107700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54276.764405] [c0000000f01077b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54276.764409] [c0000000f0107840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54276.764416] [c0000000f0107950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54276.764421] [c0000000f01079e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54276.764426] [c0000000f0107a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54276.764433] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54276.764441] [c0000000f0107d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54276.764450] [c0000000f0107de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54276.764457] [c0000000f0107ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54276.764461] [c0000000f0107f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54276.764464] rcu_preempt kthread starved for 21002 jiffies!
[54298.065323] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54298.065330] (detected by 2, t=21002 jiffies, g=3150011, c=3150010, q=6300)
[54298.065333] All QSes seen, last rcu_preempt kthread activity 21002 (4348965407-4348944405), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54298.065339] swapper/2 R running task 0 0 1 0x00000800
[54298.065341] Call Trace:
[54298.065354] [c0000000f01134b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54298.065364] [c0000000f0113530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54298.065370] [c0000000f0113680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54298.065378] [c0000000f0113700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54298.065383] [c0000000f01137b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54298.065388] [c0000000f0113840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54298.065395] [c0000000f0113950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54298.065399] [c0000000f01139e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54298.065405] [c0000000f0113a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54298.065412] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54298.065420] [c0000000f0113d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54298.065429] [c0000000f0113de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54298.065436] [c0000000f0113ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54298.065440] [c0000000f0113f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54298.065443] rcu_preempt kthread starved for 21002 jiffies!
[54319.448301] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54319.448309] (detected by 1, t=21002 jiffies, g=3150090, c=3150089, q=6304)
[54319.448313] All QSes seen, last rcu_preempt kthread activity 21002 (4348986790-4348965788), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54319.448318] swapper/1 R running task 0 0 1 0x00000800
[54319.448320] Call Trace:
[54319.448334] [c0000000f01074b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54319.448343] [c0000000f0107530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54319.448349] [c0000000f0107680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54319.448357] [c0000000f0107700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54319.448363] [c0000000f01077b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54319.448367] [c0000000f0107840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54319.448374] [c0000000f0107950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54319.448379] [c0000000f01079e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54319.448384] [c0000000f0107a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54319.448391] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54319.448399] [c0000000f0107d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54319.448407] [c0000000f0107de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54319.448414] [c0000000f0107ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54319.448419] [c0000000f0107f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54319.448422] rcu_preempt kthread starved for 21002 jiffies!
[54340.739280] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54340.739287] (detected by 1, t=21002 jiffies, g=3150152, c=3150151, q=6303)
[54340.739291] All QSes seen, last rcu_preempt kthread activity 21002 (4349008081-4348987079), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54340.739297] swapper/1 R running task 0 0 1 0x00000800
[54340.739298] Call Trace:
[54340.739312] [c0000000f01074b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54340.739322] [c0000000f0107530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54340.739328] [c0000000f0107680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54340.739336] [c0000000f0107700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54340.739341] [c0000000f01077b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54340.739345] [c0000000f0107840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54340.739352] [c0000000f0107950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54340.739357] [c0000000f01079e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54340.739362] [c0000000f0107a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54340.739369] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54340.739377] [c0000000f0107d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54340.739386] [c0000000f0107de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54340.739393] [c0000000f0107ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54340.739397] [c0000000f0107f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54340.739400] rcu_preempt kthread starved for 21002 jiffies!
[54361.095338] INFO: task INS1_RS2:2979 blocked for more than 120 seconds.
[54362.055125] Tainted: G O 4.1.35-rt41 #1
[54362.059307] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[54362.065836] INS1_RS2 D 00003fffb7dfb8d4 0 2979 2962 0x00000000
[54362.071600] Call Trace:
[54362.072744] [c00000007c072fb0] [c0000000ffe07840] 0xc0000000ffe07840 (unreliable)
[54362.078946] [c00000007c073180] [c00000000000781c] .__switch_to+0x7c/0xa0
[54362.084356] [c00000007c073200] [c000000000903fa0] .__schedule+0x360/0x740
[54362.089852] [c00000007c0732b0] [c0000000009043c4] .schedule+0x44/0x120
[54362.095087] [c00000007c073330] [c000000000906824] .schedule_timeout+0x1a4/0x260
[54362.101104] [c00000007c073430] [c00000000090537c] .wait_for_common+0xfc/0x1b0
[54362.106947] [c00000007c0734e0] [c00000000005dc88] .flush_work+0x108/0x1d0
[54362.112459] [c00000007c0735d0] [c000000000400874] .tty_buffer_flush_work+0x14/0x30
[54362.118735] [c00000007c073640] [c0000000003f8944] .n_tty_poll+0x1f4/0x2e0
[54362.124229] [c00000007c0736d0] [c0000000003f4ea4] .tty_poll+0xc4/0x100
[54362.129473] [c00000007c073770] [c00000000016ec70] .do_select+0x390/0x780
[54362.134880] [c00000007c073b70] [c00000000016f2cc] .core_sys_select+0x26c/0x360
[54362.140809] [c00000007c073d70] [c00000000016f488] .SyS_select+0xc8/0x140
[54362.146216] [c00000007c073e30] [c000000000000698] system_call+0x38/0xc4
[54362.151536] INFO: task INS2_RS2:2980 blocked for more than 120 seconds.
[54362.156848] Tainted: G O 4.1.35-rt41 #1
[54362.161029] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[54362.167557] INS2_RS2 D 00003fffb7dfb8d4 0 2980 2962 0x00000000
[54362.173320] Call Trace:
[54362.174461] [c00000007bb02fb0] [0000314d3423bc40] 0x314d3423bc40 (unreliable)
[54362.180312] [c00000007bb03180] [c00000000000781c] .__switch_to+0x7c/0xa0
[54362.185721] [c00000007bb03200] [c000000000903fa0] .__schedule+0x360/0x740
[54362.191217] [c00000007bb032b0] [c0000000009043c4] .schedule+0x44/0x120
[54362.196454] [c00000007bb03330] [c000000000906824] .schedule_timeout+0x1a4/0x260
[54362.202472] [c00000007bb03430] [c00000000090537c] .wait_for_common+0xfc/0x1b0
[54362.208314] [c00000007bb034e0] [c00000000005dc88] .flush_work+0x108/0x1d0
[54362.213847] [c00000007bb035d0] [c000000000400874] .tty_buffer_flush_work+0x14/0x30
[54362.220170] [c00000007bb03640] [c0000000003f8944] .n_tty_poll+0x1f4/0x2e0
[54362.225664] [c00000007bb036d0] [c0000000003f4ea4] .tty_poll+0xc4/0x100
[54362.231008] [c00000007bb03770] [c00000000016ec70] .do_select+0x390/0x780
[54362.236416] [c00000007bb03b70] [c00000000016f2cc] .core_sys_select+0x26c/0x360
[54362.242369] [c00000007bb03d70] [c00000000016f488] .SyS_select+0xc8/0x140
[54362.247814] [c00000007bb03e30] [c000000000000698] system_call+0x38/0xc4
[54362.549257] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54362.549264] (detected by 3, t=21002 jiffies, g=3150329, c=3150328, q=6302)
[54362.549268] All QSes seen, last rcu_preempt kthread activity 21002 (4349029891-4349008889), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54362.549273] swapper/3 R running task 0 0 1 0x00000800
[54362.549275] Call Trace:
[54362.549287] [c0000000f01174b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54362.549297] [c0000000f0117530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54362.549303] [c0000000f0117680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54362.549311] [c0000000f0117700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54362.549316] [c0000000f01177b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54362.549320] [c0000000f0117840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54362.549327] [c0000000f0117950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54362.549332] [c0000000f01179e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54362.549337] [c0000000f0117a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54362.549344] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54362.549352] [c0000000f0117d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54362.549360] [c0000000f0117de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54362.549367] [c0000000f0117ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54362.549372] [c0000000f0117f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54362.549375] rcu_preempt kthread starved for 21002 jiffies!
[54384.130237] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54384.130244] (detected by 1, t=21002 jiffies, g=3150457, c=3150456, q=6302)
[54384.130248] All QSes seen, last rcu_preempt kthread activity 21002 (4349051472-4349030470), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54384.130253] swapper/1 R running task 0 0 1 0x00000800
[54384.130255] Call Trace:
[54384.130270] [c0000000f01074b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54384.130279] [c0000000f0107530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54384.130285] [c0000000f0107680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54384.130293] [c0000000f0107700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54384.130298] [c0000000f01077b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54384.130302] [c0000000f0107840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54384.130309] [c0000000f0107950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54384.130314] [c0000000f01079e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54384.130319] [c0000000f0107a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54384.130326] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54384.130334] [c0000000f0107d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54384.130343] [c0000000f0107de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54384.130351] [c0000000f0107ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54384.130355] [c0000000f0107f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54384.130358] rcu_preempt kthread starved for 21002 jiffies!
[54406.221214] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54406.221222] (detected by 3, t=21002 jiffies, g=3150705, c=3150704, q=6302)
[54406.221225] All QSes seen, last rcu_preempt kthread activity 21002 (4349073563-4349052561), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54406.221231] swapper/3 R running task 0 0 1 0x00000800
[54406.221233] Call Trace:
[54406.221247] [c0000000f01174b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54406.221256] [c0000000f0117530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54406.221262] [c0000000f0117680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54406.221271] [c0000000f0117700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54406.221276] [c0000000f01177b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54406.221281] [c0000000f0117840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54406.221288] [c0000000f0117950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54406.221292] [c0000000f01179e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54406.221298] [c0000000f0117a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54406.221305] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54406.221312] [c0000000f0117d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54406.221321] [c0000000f0117de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54406.221328] [c0000000f0117ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54406.221333] [c0000000f0117f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54406.221335] rcu_preempt kthread starved for 21002 jiffies!
[54428.300192] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54428.300199] (detected by 3, t=21002 jiffies, g=3150942, c=3150941, q=6303)
[54428.300203] All QSes seen, last rcu_preempt kthread activity 21002 (4349095642-4349074640), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54428.300209] swapper/3 R running task 0 0 1 0x00000800
[54428.300210] Call Trace:
[54428.300225] [c0000000f01174b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54428.300234] [c0000000f0117530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54428.300240] [c0000000f0117680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54428.300249] [c0000000f0117700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54428.300254] [c0000000f01177b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54428.300259] [c0000000f0117840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54428.300266] [c0000000f0117950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54428.300270] [c0000000f01179e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54428.300275] [c0000000f0117a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54428.300282] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54428.300290] [c0000000f0117d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54428.300299] [c0000000f0117de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54428.300306] [c0000000f0117ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54428.300311] [c0000000f0117f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54428.300314] rcu_preempt kthread starved for 21002 jiffies!
[54451.129170] INFO: rcu_preempt detected stalls on CPUs/tasks:
[54451.129176] (detected by 2, t=21002 jiffies, g=3151341, c=3151340, q=6785)
[54451.129180] All QSes seen, last rcu_preempt kthread activity 21002 (4349118471-4349097469), jiffies_till_next_fqs=3, root ->qsmask 0x0
[54451.129186] swapper/2 R running task 0 0 1 0x00000800
[54451.129187] Call Trace:
[54451.129202] [c0000000f01134b0] [c0000000000735e4] .sched_show_task+0xe4/0x190 (unreliable)
[54451.129211] [c0000000f0113530] [c0000000000a6e48] .rcu_check_callbacks+0xb68/0xb70
[54451.129217] [c0000000f0113680] [c0000000000abb2c] .update_process_times+0x4c/0x90
[54451.129226] [c0000000f0113700] [c0000000000c0a88] .tick_sched_timer+0x88/0x2c0
[54451.129231] [c0000000f01137b0] [c0000000000ace2c] .__run_hrtimer.isra.34+0x8c/0x1c0
[54451.129235] [c0000000f0113840] [c0000000000ad784] .hrtimer_interrupt+0x174/0x330
[54451.129242] [c0000000f0113950] [c00000000000ec60] .__timer_interrupt+0xb0/0x1a0
[54451.129247] [c0000000f01139e0] [c00000000000f338] .timer_interrupt+0x138/0x190
[54451.129252] [c0000000f0113a80] [c000000000018040] exc_0x900_common+0x104/0x108
[54451.129260] --- interrupt: 901 at .book3e_idle+0x24/0x58
LR = .book3e_idle+0x24/0x58
[54451.129268] [c0000000f0113d70] [c0000000000085a4] .arch_cpu_idle+0x34/0xb0 (unreliable)
[54451.129276] [c0000000f0113de0] [c0000000000866bc] .cpu_startup_entry+0x28c/0x370
[54451.129284] [c0000000f0113ee0] [c00000000001e950] .start_secondary+0x2e0/0x310
[54451.129288] [c0000000f0113f90] [c00000000000046c] start_secondary_prolog+0x10/0x14
[54451.129291] rcu_preempt kthread starved for 21002 jiffies!

Any thoughts on what to tackle first ?

[yipingwang]

1. Please enabling RT in defconfig using "make menuconifg" for kernel.

CONFIG_SLAB=y

CONFIG_HIGHMEM=y

CONFIG_PREEMPT_RT_FULL=y

2. You can try to increase the RCU stall timeout. For example:

"echo 60>/sys/module/rcutree/parameters/rcu_cpu_stall_timeout"

This will not stop the jitter to the RCU stall, but increase the amount of time that this jitter must be starving a CPU. This, in turn, will make the system more tolerant of RCU stalls and will stop premature RCU stall messages from being printed .

[eric_gaucher]

Thanks for your answer. We are going to try that.

Our application works well during hours and when stall happen, linux stops, then after about 6 minutes resumes normal operation as if nothing had happened. 

A little additional question: our application uses priorities between 20 and 30 in SCHED_RR. Why do the main linux processes have such low priorities (rcu_sched at 1 SCHED_FIFO, ksoftirqd at 1 SCHED_FIFO, softirq at 0 SCHED_OTHER, ...).

Is it a normal configuration for a full preemptive kernel knowing that the real-time threads have a priority between 1 and 99 (99 highest prio).

Thanks for your answer.

[yipingwang · Accepted solution]

You could set your own priority levels on processes. To change the priority when issuing a new command you do nice -n [nice value] [command]: