[J6] 　serial8250: too much work for irq301

Hi Stanislav;

I have a customized board suffering from the same problem. I have performed power on and power down periodic booting test and could reproduce within two days.

Hardware setup is 

McASP3_AXR0 -> UART5_RXD

McASP3_AXR1 -> UART5_TXD

UART5 is weired to a GPS module. The GPS module transmits NEMA statements in 1Hz before ttyS4 is opened.

The PAD CONF registers are read as bellow:

 devmem2  0x4a00372c

/dev/mem opened.

Memory mapped at address 0xb6f34000.

Read at address  0x4A00372C (0xb6f3472c): 0x000D0004

devmem2  0x4a003730

/dev/mem opened.

Memory mapped at address 0xb6f80000.

Read at address  0x4A003730 (0xb6f80730): 0x000D0004

The software is compiled from GLSDK 7.03.0.03.

When it happens, the system is stalled with back trace as bellow

[   26.659808] INFO: rcu_preempt self-detected stall on CPU { 0}  (t=2100 jiffies g=4294967222 c=4294967221 q=3582)

[   26.670055] CPU: 0 PID: 1250 Comm: locationservice Tainted: P           O 3.14.57 #3

[   26.677845] [<c0011415>] (unwind_backtrace) from [<c000ee9f>] (show_stack+0xb/0xc)

[   26.685453] [<c000ee9f>] (show_stack) from [<c032247f>] (dump_stack+0x4b/0x80)

[   26.692710] [<c032247f>] (dump_stack) from [<c0053165>] (rcu_check_callbacks+0x30d/0x618)

[   26.700927] [<c0053165>] (rcu_check_callbacks) from [<c002c01f>] (update_process_times+0x2b/0x44)

[   26.709840] [<c002c01f>] (update_process_times) from [<c0059cfb>] (tick_sched_timer+0x2b/0x4c)

[   26.718491] [<c0059cfb>] (tick_sched_timer) from [<c0038641>] (__run_hrtimer+0x29/0x80)

[   26.726532] [<c0038641>] (__run_hrtimer) from [<c0038d9b>] (hrtimer_interrupt+0xd7/0x20c)

[   26.734749] [<c0038d9b>] (hrtimer_interrupt) from [<c02622a7>] (arch_timer_handler_virt+0x1f/0x24)

[   26.743750] [<c02622a7>] (arch_timer_handler_virt) from [<c004eaf5>] (handle_percpu_devid_irq+0x39/0x48)

[   26.753273] [<c004eaf5>] (handle_percpu_devid_irq) from [<c004c833>] (generic_handle_irq+0x13/0x1c)

[   26.762360] [<c004c833>] (generic_handle_irq) from [<c000d4bb>] (handle_IRQ+0x23/0x60)

[   26.770312] [<c000d4bb>] (handle_IRQ) from [<c00083c3>] (gic_handle_irq+0x1f/0x48)

[   26.777916] [<c00083c3>] (gic_handle_irq) from [<c000f65b>] (__irq_svc+0x3b/0x80)

[   26.785426] Exception stack(0xe89f9c30 to 0xe89f9c78)

[   26.790498] 9c20:                                     00000000 c055fc00 0000000a 00000000

[   26.798710] 9c40: 00000002 00000013 00000000 e89f8000 fa212000 00000000 000000b8 0000001a

[   26.806920] 9c60: a2aaaaa3 e89f9c78 c0027def c0027dfe 40000133 ffffffff

[   26.813565] [<c000f65b>] (__irq_svc) from [<c0027dfe>] (__do_softirq+0x66/0x17c)

[   26.820992] [<c0027dfe>] (__do_softirq) from [<c00280e3>] (irq_exit+0x6f/0xa0)

[   26.828245] [<c00280e3>] (irq_exit) from [<c000d4bf>] (handle_IRQ+0x27/0x60)

[   26.835324] [<c000d4bf>] (handle_IRQ) from [<c00083c3>] (gic_handle_irq+0x1f/0x48)

[   26.842927] [<c00083c3>] (gic_handle_irq) from [<c000f65b>] (__irq_svc+0x3b/0x80)

[   26.850437] Exception stack(0xe89f9ce8 to 0xe89f9d30)

[   26.855507] 9ce0:                   c0594224 00000010 0000000b 00000006 c0594224 e8b68eac

[   26.863719] 9d00: ea773a10 0001c200 00000013 00000020 000000b8 0000001a 38dc6c00 e89f9d30

[   26.871929] 9d20: c01d57e1 c0324e1e 00000033 ffffffff

[   26.877005] [<c000f65b>] (__irq_svc) from [<c0324e1e>] (_raw_spin_unlock_irq+0x16/0x3c)

[   26.885045] [<c0324e1e>] (_raw_spin_unlock_irq) from [<c01d57e1>] (omap_8250_set_termios+0x1c9/0x2ac)

[   26.894305] [<c01d57e1>] (omap_8250_set_termios) from [<c01d3cd9>] (serial8250_set_termios+0x9/0x14)

[   26.903480] [<c01d3cd9>] (serial8250_set_termios) from [<c01d103b>] (uart_change_speed+0x4b/0x5c)

[   26.912392] [<c01d103b>] (uart_change_speed) from [<c01d10a3>] (uart_set_termios+0x57/0x180)

[   26.920868] [<c01d10a3>] (uart_set_termios) from [<c01c4379>] (tty_set_termios+0x111/0x238)

[   26.929255] [<c01c4379>] (tty_set_termios) from [<c01c481f>] (set_termios+0x18f/0x1b4)

[   26.937204] [<c01c481f>] (set_termios) from [<c01c4ae7>] (tty_mode_ioctl+0x223/0x390)

[   26.945067] [<c01c4ae7>] (tty_mode_ioctl) from [<c01c1071>] (tty_ioctl+0x1f1/0x878)

[   26.952756] [<c01c1071>] (tty_ioctl) from [<c0096691>] (do_vfs_ioctl+0x59/0x404)

[   26.960184] [<c0096691>] (do_vfs_ioctl) from [<c0096a7d>] (SyS_ioctl+0x41/0x4c)

[   26.967524] [<c0096a7d>] (SyS_ioctl) from [<c000cc21>] (ret_fast_syscall+0x1/0x4e)

It seems to be more likely happen in set_termios().

I dump IIR and LSR register in 8250 chain IRQ hanlder.

[    5.646708] serial8250: too much work for irq301

[    5.651353] uart4: irq:514 status:e0 iir:c6 tx:0 rx:14 fe:1 pe:0 brk:0 oe:0

[    5.659533] serial8250: too much work for irq301

[    5.664172] uart4: irq:1028 status:e0 iir:c6 tx:0 rx:92 fe:2 pe:0 brk:0 oe:1

[    5.672286] serial8250: too much work for irq301

[    5.676924] uart4: irq:1542 status:e0 iir:c6 tx:0 rx:168 fe:2 pe:0 brk:0 oe:2

[    5.685147] serial8250: too much work for irq301

[    5.689782] uart4: irq:2056 status:e0 iir:c6 tx:0 rx:244 fe:2 pe:0 brk:0 oe:3

[    5.698001] serial8250: too much work for irq301

[    5.702636] uart4: irq:2570 status:e0 iir:c6 tx:0 rx:320 fe:2 pe:0 brk:0 oe:4

UART5 trigger interrupt  ~50000 times per second. The IIR and LSR registers contents are weired to me.

IIR = 0xc6 means RLSI (Receiver line status interrupt) which is interpreted as Receiver line status interrupt according to DRA7 TRM.

LSR=0xe0 means FIFOE and TEMT and THRE.

#define UART_LSR	5	/* In:  Line Status Register */
#define UART_LSR_FIFOE		0x80 /* Fifo error */
#define UART_LSR_TEMT		0x40 /* Transmitter empty */
#define UART_LSR_THRE		0x20 /* Transmit-hold-register empty */
#define UART_LSR_BI		0x10 /* Break interrupt indicator */
#define UART_LSR_FE		0x08 /* Frame error indicator */
#define UART_LSR_PE		0x04 /* Parity error indicator */
#define UART_LSR_OE		0x02 /* Overrun error indicator */
#define UART_LSR_DR		0x01 /* Receiver data ready */
#define UART_LSR_BRK_ERROR_BITS	0x1E /* BI, FE, PE, OE bits */

According to DRA7 TRM, FIFOE means at least one of Break interrupt, Frame error and parity error in RX FIFO. However  none of BRK_ERROR_BITS is set.

I found related thread[1] about "too much irq" but still haven't any conclusion.

Could you provide any advise?

Thanks!

[1]. www.gossamer-threads.com/.../2106110

Hi Stanislav;

Forgive my thoughtless. I misunderstood and checked WAKEUPENABLE bit of  PADCONF instread of UART_SYSC.

UART_SYSC is 0xD, same as Andy's.  It is handled by omap_hwmod completely.

arch/arm/mach-omap2/omap_hwmod.c

static void _enable_sysc(struct omap_hwmod *oh)
{
......
	if (sf & SYSC_HAS_SIDLEMODE) {
		if (oh->flags & HWMOD_SWSUP_SIDLE ||
		    oh->flags & HWMOD_SWSUP_SIDLE_ACT) {
			idlemode = HWMOD_IDLEMODE_NO;
		}
......

I don't understand why it should be HWMOD_IDLEMODE_NO in case of HWMOD_SWSUP_SIDLE_ACT. I checked hwmod of omap3, omap4 and omap5, the flag of UART module is always HWMOD_SWSUP_SIDLE_ACT.

Anyway, I will do some test with WAKEUP disabled.

Regards,

Totoro

Hi Andy,

Would you explain how to turn off wakeup event?

a.  Write UART_SYSC to clear ENAWAKEUP in 8250_omap.c driver

Or

b. remove SYSC_HAS_ENAWAKEUP from sysc_flags

static struct omap_hwmod_class_sysconfig dra7xx_uart_sysc = {
	.rev_offs	= 0x0050,
	.sysc_offs	= 0x0054,
	.syss_offs	= 0x0058,
	.sysc_flags	= (SYSC_HAS_AUTOIDLE | SYSC_HAS_ENAWAKEUP |
			   SYSC_HAS_SIDLEMODE | SYSC_HAS_SOFTRESET |
			   SYSS_HAS_RESET_STATUS),
	.idlemodes	= (SIDLE_FORCE | SIDLE_NO | SIDLE_SMART |
			   SIDLE_SMART_WKUP),
	.sysc_fields	= &omap_hwmod_sysc_type1,
};

Or

c. clear UART_WER register of UART5

	/* Enable module level wake up */
	priv->wer = OMAP_UART_WER_MOD_WKUP;
	if (priv->habit & OMAP_UART_WER_HAS_TX_WAKEUP)
		priv->wer |= OMAP_UART_TX_WAKEUP_EN;
	serial_out(up, UART_OMAP_WER, priv->wer);

Regards

Totoro

Hi Andy,

Very sorry for being busy in other stuffs last week. I will start booting test tomorrow with wake-up disabled.

I wonder how many UART(ttySx) are used on your board? Is there any proccess opening any ttyS device when 8250 comlained about “too much work”？

8250 driver handles irqs as chained irqs. suprious irq from any uart controller could be the cause of "too much work for irq301".

Regard,

Totoro

Hi Stanislav, Andy,

I dumped SCR, IER, WER and IER2 at the end of set_termios as 

SCR = 0x0; IER=0x5; WER=0xff; IER2=0.

I tested with wakeup disabbled but still reproduced within 10hours. Patch as bellow

--- a/arch/arm/mach-omap2/omap_hwmod_7xx_g5_data.c
+++ b/arch/arm/mach-omap2/omap_hwmod_7xx_g5_data.c
@@ -2473,7 +2473,7 @@ static struct omap_hwmod_class_sysconfig dra7xx_uart_sysc = {
 	.rev_offs	= 0x0050,
 	.sysc_offs	= 0x0054,
 	.syss_offs	= 0x0058,
-	.sysc_flags	= (SYSC_HAS_AUTOIDLE | SYSC_HAS_ENAWAKEUP |
+	.sysc_flags	= (SYSC_HAS_AUTOIDLE |
 			   SYSC_HAS_SIDLEMODE | SYSC_HAS_SOFTRESET |
 			   SYSS_HAS_RESET_STATUS),
 	.idlemodes	= (SIDLE_FORCE | SIDLE_NO | SIDLE_SMART |
@@ -2524,7 +2524,7 @@ static struct omap_hwmod dra7xx_uart5_hwmod = {
 	.class		= &dra7xx_uart_hwmod_class,
 	.clkdm_name	= "l4per_clkdm",
 	.main_clk	= "uart5_gfclk_mux",
-	.flags		= HWMOD_SWSUP_SIDLE_ACT,
+	/*.flags		= HWMOD_SWSUP_SIDLE_ACT,*/
 	.prcm = {
 		.omap4 = {
 			.clkctrl_offs = DRA7XX_CM_L4PER_UART5_CLKCTRL_OFFSET,

--- a/drivers/tty/serial/8250/8250_omap.c
+++ b/drivers/tty/serial/8250/8250_omap.c
@@ -581,10 +581,11 @@ static int omap_8250_startup(struct uart_port *port)
 	up->capabilities |= UART_CAP_RPM;
 #endif
 
-	/* Enable module level wake up */
-	priv->wer = OMAP_UART_WER_MOD_WKUP;
-	if (priv->habit & OMAP_UART_WER_HAS_TX_WAKEUP)
-		priv->wer |= OMAP_UART_TX_WAKEUP_EN;
+	/* disable module level wake up */
+	/*priv->wer = OMAP_UART_WER_MOD_WKUP;*/
+	/*if (priv->habit & OMAP_UART_WER_HAS_TX_WAKEUP)*/
+		/*priv->wer |= OMAP_UART_TX_WAKEUP_EN;*/
+	priv->wer = 0;
 	serial_out(up, UART_OMAP_WER, priv->wer);
 
 	if (up->dma)

Regards,
Totoro

Hi Totoro,
You said previously:
"LSR=0xe0 means FIFOE and TEMT and THRE."
1. But how many times you are reading LSR? Take into account that single read from LSR will end the OVERRUN interrupt condition and you will not be able to detect it at next LSR read.
2. Also, for framing error (FE,PE,BI) make sure you are not reading RHR register beforehand, as read from RHR will end the interrupt condition.

Besides that, I agree that LSR[7] FIFO ERROR is strange to be set without the 4 FIFO error bits. This might be a HW bug but I cannot find this documented in errata.
For sure I know that, if LSR[7] is always set, it will generate endless interrupt request, which can cause the "too much work..."
Now we must find out what causes LSR[7] to be set and why it is not cleared.
Can you check the 1. and 2. conditions above?

Thanks,
Stan

Hi Stan;

Forgot to mention that I had not read and printed LSR and IIR directly.

Instead RHR, IIR and LSR are handled by Linux 8250 driver. I just add  shadows into struct uart_8250_port. Every time 8250 handles IRQ, I save IIR and LSR to the shadows. When "too much work for irqxxx" happens, the shadows will be printed to console.

Is that OK?

Regards,

Totoro