网卡驱动死机调试经验案例

一、现象

执行iperf打流后，不管是udp打流还是tcp打流，命令行没有响应，无法敲入任何字符，也没有回显，但一段时间后，串口有打印，查看代码后，发现是EMAC的DMA中断里打印的，打印的内容如下：

[13:39:23:743]37.4320 Mbps!
[13:39:46:157]37.4490 Mbps!
[13:40:08:589]37.4490 Mbps!
[14:26:59:361]intr 0x86980c0
[14:27:02:590]intr 0x8688080
[14:27:03:390]intr 0x8688080
[14:27:11:837]intr 0x8688080
[14:27:15:579]intr 0x8688080
[14:27:16:331]intr 0x8688080
[14:27:28:217]intr 0x8688080
[14:27:30:680]intr 0x8688080
[14:27:35:575]intr 0x8688080
[14:27:42:598]intr 0x8688080
[14:27:45:103]intr 0x8688080
………

二、问题排查

首先找到打印对应的中断函数，如下所示：

irqreturn_t vmc_interrupt(int irqno, void *param)
{
    struct emac_device *edev = (struct emac_device *)param;
    struct eth_device *eth = &edev->parent;
    int ints = emac_read_reg((u32 *)(edev->dma_base), DmaStatus);
    int en = emac_read_reg((u32 *)(edev->dma_base), DmaInterrupt);
	
    emac_write_reg((u32 *)(edev->dma_base), DmaStatus, ints);
    emac_write_reg((u32 *)(edev->dma_base), DmaInterrupt, 0);
	
    if (ints & DmaIntTxCompleted) 
	{
		rt_event_send(emac_event, EMAC_EVENT_TX_COMPLETE);
    }
	
    if (ints & DmaIntRxCompleted) 
	{
        eth_device_ready(eth);
    }

    if (ints & DmaIntAbnormal) 
	{
        EMAC_PRINTF(VIM_EMAC_DEBUG, "intr 0x%x\n", ints);
    }

    emac_write_reg((u32 *)(edev->dma_base), DmaInterrupt, en);
	return 0;
}

可以看到，是发生了异常的DMA中断打印的，第一个异常的DmaStatus寄存器值是0x86980c0，对照寄存器手册发现网卡接收DMA块被用完了，如下所示。

在注意到死机时的串口打印时间，异常日志与正常iperf打流的最后一条日志相差了46分钟，因此可以推测是这段时间内网卡的接收函数没有执行，导致网卡DMA接收buffer消耗殆尽，从串口不能输入也侧面印证了这一点，因此可以推测程序可能是死在某个循环里了，可能是比网卡接收线程、shell线程优先级更高的线程，或是卡在某个中断里出不来了。

为了验证是否卡在线程里，有很多种办法，例如在rtt线程调度器里加打印，看是从哪个线程切到哪个线程最后卡住了，但是这样打印会非常多，所以简单的办法就是提高shell线程的优先级去验证，实测把shell现场优先级提高最高，仍然会死机，因此可以推测大概率是卡死在中断里了。这里直接用Jlink+GDB调试的方式去验证，结果每次全速运行暂停时，程序总停在中断里，中断入口函数如下所示，其中cnt是调试加的，当一直卡在中断里出不来时，会打印对应的中断号，果然这个中断号和EMAC的中断号是一致的。

void gic_handle_irq(irq_regs_t *regs)
{
    uint32_t irqstat, irqnr;
    static uint32_t cnt = 0;

    do
    {
        irqstat = readl(GIC_CPU_AIAR_REG);
        irqnr = irqstat & GICC_IAR_INT_ID_MASK;

        if (likely(irqnr > 15 && irqnr < 1020))
        {
            writel(irqstat, GIC_CPU_AEOI_REG);
            isb();
            handle_domain_irq(NULL, irqnr, regs);
			if(++cnt > 1000)
			{
				cnt = 0;
				__log("int %d",irqnr);
			}
            continue;
        }
        if (irqnr < 16)
        {
            writel(irqstat, GIC_CPU_AEOI_REG);
            writel(irqstat, GIC_CPU_DEACTIVATE);
#ifdef RT_USING_SMP
            /*
            ¦* Ensure any shared data written by the CPU sending
            ¦* the IPI is read after we've read the ACK register
            ¦* on the GIC.
            ¦*
            ¦* Pairs with the write barrier in gic_raise_softirq
            ¦*/
            smp_rmb();
            handle_IPI(irqnr, regs);
#endif
            continue;
        }
		cnt = 0;
        break;
    } while (1);
}

因此可以推测是EMAC的某个中断没清除导致反复进入EMAC的中断，细查发现正常DmaStatus寄存器的bit27是0，每次卡住时这个位都是1，这个bit位的描述如下：

查看代码和寄存器手册发现EMAC不止DmaStatus这个状态寄存器，还有个GmacInterruptStatus，于是异常时将这个寄存器的值也打印出来，发现是0x50，对应的寄存器描述如下：

好吧，这个寄存器描述讲了个寂寞，于是看linux sdk的代码，发现有个函数叫vmc_emac_disable_mmc_tx_interrupt，好像和这个有点关系，再看这个函数操作的寄存器，实际是屏蔽了和发送统计相关的功能，这个寄存器有25个bit位，刚好对应25种发送数据统计。在linux sdk里，所有的mask都置1了，相当于关闭了所有的发送统计。虽然没有功能说明什么时候会产生中断，但翻过头看串口日志发现，每次都是打印了19次iperf结果后卡住，怀疑应该是发送的数据量达到了某个数，比如超过32位的数据量时，会产生对应的中断，而这个中断没有去清除。

三、问题修复

参考linux sdk的做法，将发送和接收的统计功能关闭，问题不再复现。