Excessive logging causing rcu_sched_state stall (wait_for_xmitr 8250.c)

Excessive logging causing rcu_sched_state stall (wait_for_xmitr 8250.c)

[helpmelearn]

Hi,
It's been more than a week since I am stuck with this. I am relatively a
newbie venturing into linux
kernel, so please be gentle.

I have a non-tained 2.6.35.14 kernel that needs to output a lot using the
serial console. To reproduce I 
simply run klogd -2 -c 7 and this causes rcu_sched_state to detect stall
with a trace such as pasted 
below. 

Please note that I had enabled CONFIG_PROVE_RCU, CONFIG_RCU_TRACE and
related flags as well as 
bumped RCU_STALL_RAT_DELAY to 20 while debugging. This makes RCU wait 15020
jiffies until it 
complains. Otherwise, it complains in 10002 jiffies (with default config).

The trace points to the wait_for_xmitr() loop in 8250.c (from another run):

(gdb) list *(wait_for_xmitr+0x56)
0x5ae is in wait_for_xmitr (drivers/serial/8250.c:1863).
1858    {
1859            unsigned int status, tmout = 10000;
1860
1861            /* Wait up to 10ms for the character(s) to be sent. */
1862            do {
1863                    status = serial_in(up, UART_LSR);
1864
1865                    up->lsr_saved_flags |= status & LSR_SAVE_FLAGS;
1866
1867                    if (--tmout == 0)
(gdb)

AFAICT, this piece of code is run with interrupts disabled. So is the issue
here simply that too much 
output is causing wait_for_xmitr() loop to run for longer than
rcu_sched_state() is happy with?

In rcu/stallwarn.txt, Paul notes that rcu_sched_state() will get unhappy
should the CPU loop with 
interrupts disabled.

IF this is indeed the case, what would be a potential fix for this? Any
help/guidance much appreciated. 
Thank you!

[  346.664471] INFO: rcu_sched_state detected stalls on CPUs/tasks: { 5}
(detected by 0, t=15020 jiffies)
[  346.664477] sending NMI to all CPUs:
[  346.666532] NMI backtrace for cpu 5
[  346.666534] CPU 5
[  346.666535] Modules linked in: ipmi_devintf ipmi_si ipmi_msghandler
iscsi_scst crc32c_intel iptable_filter xt_NOTRACK iptable_nat nf_nat
nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 iptable_raw ip_tables x_tables
bonding qla2x00tgt qla2xxx scsi_transport_fc scst_vdisk scst vtms softdog
coretemp hwmon dm_mod video backlight output serio_raw rtc_cmos rtc_core
rtc_lib button ixgbe i2c_i801 i2c_core uhci_hcd pcspkr
[  346.666559]
[  346.666562] Pid: 0, comm: swapper Not tainted 2.6.35-14EIsmp
X8DTH/X8DTH-i/6/iF/6F
[  346.666565] RIP: 0010:[<ffffffff812939b4>]  [<ffffffff812939b4>]
io_serial_in+0x10/0x15
[  346.666571] RSP: 0018:ffff880144223a70  EFLAGS: 00000002
[  346.666574] RAX: 0000000000000900 RBX: ffffffff82a5c8c0 RCX:
0000000000000000
[  346.666576] RDX: 00000000000003fd RSI: 0000000000000005 RDI:
ffffffff82a5c8c0
[  346.666579] RBP: ffff880144223a70 R08: 0000000098a41ff0 R09:
ffffffff81293831
[  346.666581] R10: ffffffff81d4db2b R11: 0000000000000000 R12:
0000000000000000
[  346.666583] R13: 00000000000025af R14: 0000000000000020 R15:
000000000000003e
[  346.666586] FS:  0000000000000000(0000) GS:ffff880144220000(0000)
knlGS:0000000000000000
[  346.666589] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[  346.666591] CR2: 00007fff5f13d464 CR3: 0000000074531000 CR4:
00000000000006e0
[  346.666594] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[  346.666596] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7:
0000000000000400
[  346.666599] Process swapper (pid: 0, threadinfo ffff88013fb44000, task
ffff88023fb1e000)
[  346.666600] Stack:
[  346.666602]  ffff880144223aa0 ffffffff81291b6d ffffffff82a5c8c0
000000000000000a
[  346.666605] <0> ffffffff81291bd6 ffffffff82a5c8c0 ffff880144223ac0
ffffffff81291bf5
[  346.666608] <0> ffffffff81d4dc59 000000000000003e ffff880144223b00
ffffffff8128e79b
[  346.666612] Call Trace:
[  346.666614]  <IRQ>
[  346.666617]  [<ffffffff81291b6d>] wait_for_xmitr+0x38/0xa1
[  346.666621]  [<ffffffff81291bd6>] ? serial8250_console_putchar+0x0/0x34
[  346.666624]  [<ffffffff81291bf5>] serial8250_console_putchar+0x1f/0x34
[  346.666627]  [<ffffffff8128e79b>] uart_console_write+0x41/0x52
[  346.666631]  [<ffffffff8129388c>] serial8250_console_write+0xb2/0x116
[  346.666635]  [<ffffffff8103e4dd>] __call_console_drivers+0x67/0x79
[  346.666638]  [<ffffffff8103e54a>] _call_console_drivers+0x5b/0x5f
[  346.666641]  [<ffffffff8103e937>] release_console_sem+0x12a/0x1c5
[  346.666644]  [<ffffffff8103efaf>] vprintk+0x373/0x3a3
[  346.666648]  [<ffffffff8103f046>] ? printk+0x67/0x69
[  346.666651]  [<ffffffff8103f046>] printk+0x67/0x69
[  346.666655]  [<ffffffff81214645>] ? __delay+0xa/0xc
[  346.666659]  [<ffffffff8105b3ef>] ? up+0xf/0x39
[  346.666663]  [<ffffffff8106597e>] ? trace_hardirqs_on+0xd/0xf
[  346.666692]  [<ffffffffa011b2d2>] ? debug_print_prefix+0x135/0x146 [scst]
[  346.666706]  [<ffffffffa00f6ad3>] scst_process_redirect_cmd+0x97/0x323
[scst]
[  346.666720]  [<ffffffffa00f8807>] scst_cmd_done_local+0x227/0x280 [scst]
[  346.666726]  [<ffffffffa0186d61>] blockio_endio+0xcf/0xee [scst_vdisk]
[  346.666733]  [<ffffffffa0085324>] ? end_io_acct+0x0/0x147 [dm_mod]
[  346.666736]  [<ffffffff811026a7>] bio_endio+0x26/0x28
[  346.666742]  [<ffffffffa00855c5>] dec_pending+0x15a/0x163 [dm_mod]
[  346.666748]  [<ffffffffa008576a>] clone_endio+0xa1/0xae [dm_mod]
[  346.666752]  [<ffffffff811026a7>] bio_endio+0x26/0x28
[  346.666759]  [<ffffffffa00bff51>] vtms_softirq_done+0xeb/0x107 [vtms]
[  346.666764]  [<ffffffff8120127f>] blk_done_softirq+0x6d/0x7e
[  346.666767]  [<ffffffff810439fc>] __do_softirq+0xe9/0x1c7
[  346.666771]  [<ffffffff8100384c>] call_softirq+0x1c/0x34
[  346.666774]  [<ffffffff81004e15>] do_softirq+0x38/0x83
[  346.666777]  [<ffffffff81043911>] irq_exit+0x45/0x47
[  346.666780]  [<ffffffff81017c43>]
smp_call_function_single_interrupt+0x2f/0x31
[  346.666784]  [<ffffffff810034b3>]
call_function_single_interrupt+0x13/0x20
[  346.666786]  <EOI>

-- 
View this message in context: http://old.nabble.com/Excessive-logging-causing-rcu_sched_state-stall-%28wait_for_xmitr-8250.c%29-tp33854911p33854911.html
Sent from the linux-serial mailing list archive at Nabble.com.

Excessive logging causing rcu_sched_state stall (wait_for_xmitr 8250.c)

[joe shmoe]

Hi, 
It's been more than a week since I am stuck with this. I am relatively a newbie venturing into linux 
kernel, so please be gentle. 

I have a non-tained 2.6.35.14 kernel that needs to output a lot using the serial console. To reproduce I 
simply run klogd -2 -c 7 and this causes rcu_sched_state to detect stall with a trace such as pasted 
below. 


Please note that I had enabled CONFIG_PROVE_RCU, CONFIG_RCU_TRACE and related flags as well as 
bumped RCU_STALL_RAT_DELAY to 20 while debugging. This makes RCU wait 15020 jiffies until it 
complains. Otherwise, it complains in 10002 jiffies (with default config). 

The trace points to the wait_for_xmitr() loop in 8250.c (from another run): 

(gdb) list *(wait_for_xmitr+0x56) 
0x5ae is in wait_for_xmitr (drivers/serial/8250.c:1863). 
1858    { 
1859            unsigned int status, tmout = 10000; 
1860 
1861            /* Wait up to 10ms for the character(s) to be sent. */ 
1862            do { 
1863                    status = serial_in(up, UART_LSR); 
1864 
1865                    up->lsr_saved_flags |= status & LSR_SAVE_FLAGS; 
1866 
1867                    if (--tmout == 0) 
(gdb) 

AFAICT, this piece of code is run with interrupts disabled. So is the issue here simply that too much 
output is causing wait_for_xmitr() loop to run for longer than rcu_sched_state() is happy with? 

In rcu/stallwarn.txt, Paul notes that rcu_sched_state() will get unhappy should the CPU loop with 
interrupts disabled. 

IF this is indeed the case, what would be a potential fix for this? Any help/guidance much appreciated. 
Thank you! 

[  346.664471] INFO: rcu_sched_state detected stalls on CPUs/tasks: { 5} (detected by 0, t=15020 jiffies) 
[  346.664477] sending NMI to all CPUs: 
[  346.666532] NMI backtrace for cpu 5 
[  346.666534] CPU 5 
[  346.666535] Modules linked in: ipmi_devintf ipmi_si 
ipmi_msghandler iscsi_scst crc32c_intel iptable_filter xt_NOTRACK 
iptable_nat nf_nat nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 
iptable_raw ip_tables x_tables bonding qla2x00tgt qla2xxx 
scsi_transport_fc scst_vdisk scst vtms softdog coretemp hwmon dm_mod 
video backlight output serio_raw rtc_cmos rtc_core rtc_lib button ixgbe 
i2c_i801 i2c_core uhci_hcd pcspkr 
[  346.666559] 
[  346.666562] Pid: 0, comm: swapper Not tainted 2.6.35-14EIsmp X8DTH/X8DTH-i/6/iF/6F 
[  346.666565] RIP: 0010:[<ffffffff812939b4>]  [<ffffffff812939b4>] io_serial_in+0x10/0x15 
[  346.666571] RSP: 0018:ffff880144223a70  EFLAGS: 00000002 
[  346.666574] RAX: 0000000000000900 RBX: ffffffff82a5c8c0 RCX: 0000000000000000 
[  346.666576] RDX: 00000000000003fd RSI: 0000000000000005 RDI: ffffffff82a5c8c0 
[  346.666579] RBP: ffff880144223a70 R08: 0000000098a41ff0 R09: ffffffff81293831 
[  346.666581] R10: ffffffff81d4db2b R11: 0000000000000000 R12: 0000000000000000 
[  346.666583] R13: 00000000000025af R14: 0000000000000020 R15: 000000000000003e 
[  346.666586] FS:  0000000000000000(0000) GS:ffff880144220000(0000) knlGS:0000000000000000 
[  346.666589] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b 
[  346.666591] CR2: 00007fff5f13d464 CR3: 0000000074531000 CR4: 00000000000006e0 
[  346.666594] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 
[  346.666596] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 
[  346.666599] Process swapper (pid: 0, threadinfo ffff88013fb44000, task ffff88023fb1e000) 
[  346.666600] Stack: 
[  346.666602]  ffff880144223aa0 ffffffff81291b6d ffffffff82a5c8c0 000000000000000a 
[  346.666605] <0> ffffffff81291bd6 ffffffff82a5c8c0 ffff880144223ac0 ffffffff81291bf5 
[  346.666608] <0> ffffffff81d4dc59 000000000000003e ffff880144223b00 ffffffff8128e79b 
[  346.666612] Call Trace: 
[  346.666614]  <IRQ> 
[  346.666617]  [<ffffffff81291b6d>] wait_for_xmitr+0x38/0xa1 
[  346.666621]  [<ffffffff81291bd6>] ? serial8250_console_putchar+0x0/0x34 
[  346.666624]  [<ffffffff81291bf5>] serial8250_console_putchar+0x1f/0x34 
[  346.666627]  [<ffffffff8128e79b>] uart_console_write+0x41/0x52 
[  346.666631]  [<ffffffff8129388c>] serial8250_console_write+0xb2/0x116 
[  346.666635]  [<ffffffff8103e4dd>] __call_console_drivers+0x67/0x79 
[  346.666638]  [<ffffffff8103e54a>] _call_console_drivers+0x5b/0x5f 
[  346.666641]  [<ffffffff8103e937>] release_console_sem+0x12a/0x1c5 
[  346.666644]  [<ffffffff8103efaf>] vprintk+0x373/0x3a3 
[  346.666648]  [<ffffffff8103f046>] ? printk+0x67/0x69 
[  346.666651]  [<ffffffff8103f046>] printk+0x67/0x69 
[  346.666655]  [<ffffffff81214645>] ? __delay+0xa/0xc 
[  346.666659]  [<ffffffff8105b3ef>] ? up+0xf/0x39 
[  346.666663]  [<ffffffff8106597e>] ? trace_hardirqs_on+0xd/0xf 
[  346.666692]  [<ffffffffa011b2d2>] ? debug_print_prefix+0x135/0x146 [scst] 
[  346.666706]  [<ffffffffa00f6ad3>] scst_process_redirect_cmd+0x97/0x323 [scst] 
[  346.666720]  [<ffffffffa00f8807>] scst_cmd_done_local+0x227/0x280 [scst] 
[  346.666726]  [<ffffffffa0186d61>] blockio_endio+0xcf/0xee [scst_vdisk] 
[  346.666733]  [<ffffffffa0085324>] ? end_io_acct+0x0/0x147 [dm_mod] 
[  346.666736]  [<ffffffff811026a7>] bio_endio+0x26/0x28 
[  346.666742]  [<ffffffffa00855c5>] dec_pending+0x15a/0x163 [dm_mod] 
[  346.666748]  [<ffffffffa008576a>] clone_endio+0xa1/0xae [dm_mod] 
[  346.666752]  [<ffffffff811026a7>] bio_endio+0x26/0x28 
[  346.666759]  [<ffffffffa00bff51>] vtms_softirq_done+0xeb/0x107 [vtms] 
[  346.666764]  [<ffffffff8120127f>] blk_done_softirq+0x6d/0x7e 
[  346.666767]  [<ffffffff810439fc>] __do_softirq+0xe9/0x1c7 
[  346.666771]  [<ffffffff8100384c>] call_softirq+0x1c/0x34 
[  346.666774]  [<ffffffff81004e15>] do_softirq+0x38/0x83 
[  346.666777]  [<ffffffff81043911>] irq_exit+0x45/0x47 
[  346.666780]  [<ffffffff81017c43>] smp_call_function_single_interrupt+0x2f/0x31 
[  346.666784]  [<ffffffff810034b3>] call_function_single_interrupt+0x13/0x20 
[  346.666786]  <EOI> 
--
To unsubscribe from this list: send the line "unsubscribe linux-serial" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Excessive logging causing rcu_sched_state stall (wait_for_xmitr 8250.c)

[Greg KH]

On Tue, May 15, 2012 at 05:41:28PM -0700, joe shmoe wrote:
> Hi, 
> It's been more than a week since I am stuck with this. I am relatively a newbie venturing into linux 
> kernel, so please be gentle. 
> 
> I have a non-tained 2.6.35.14 kernel that needs to output a lot using the serial console. To reproduce I 
> simply run klogd -2 -c 7 and this causes rcu_sched_state to detect stall with a trace such as pasted 
> below. 

Does running 3.3, or 3.4-rc6 show the same problems?  I ask as 2.6.35
really is very old and not supported much at all, and tens of thousands
of changes to the kernel have happened since then.

So if you could check the latest kernel, that would be great.

thanks,

greg k-h