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@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
