一、现象
执行iperf打流后,不管是udp打流还是tcp打流,命令行没有响应,无法敲入任何字符,也没有回显,但一段时间后,串口有打印,查看代码后,发现是EMAC的DMA中断里打印的,打印的内容如下:
[13:39:23:743]37.4320Mbps![13:39:46:157]37.4490Mbps![13:40:08:589]37.4490Mbps![14:26:59:361]intr0x86980c0[14:27:02:590]intr0x8688080[14:27:03:390]intr0x8688080[14:27:11:837]intr0x8688080[14:27:15:579]intr0x8688080[14:27:16:331]intr0x8688080[14:27:28:217]intr0x8688080[14:27:30:680]intr0x8688080[14:27:35:575]intr0x8688080[14:27:42:598]intr0x8688080[14:27:45:103]intr0x8688080………二、问题排查
首先找到打印对应的中断函数,如下所示:
irqreturn_tvmc_interrupt(intirqno,void*param){structemac_device*edev=(structemac_device*)param;structeth_device*eth=&edev->parent;intints=emac_read_reg((u32*)(edev->dma_base),DmaStatus);inten=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);return0;}可以看到,是发生了异常的DMA中断打印的,第一个异常的DmaStatus寄存器值是0x86980c0,对照寄存器手册发现网卡接收DMA块被用完了,如下所示。
在注意到死机时的串口打印时间,异常日志与正常iperf打流的最后一条日志相差了46分钟,因此可以推测是这段时间内网卡的接收函数没有执行,导致网卡DMA接收buffer消耗殆尽,从串口不能输入也侧面印证了这一点,因此可以推测程序可能是死在某个循环里了,可能是比网卡接收线程、shell线程优先级更高的线程,或是卡在某个中断里出不来了。
为了验证是否卡在线程里,有很多种办法,例如在rtt线程调度器里加打印,看是从哪个线程切到哪个线程最后卡住了,但是这样打印会非常多,所以简单的办法就是提高shell线程的优先级去验证,实测把shell现场优先级提高最高,仍然会死机,因此可以推测大概率是卡死在中断里了。这里直接用Jlink+GDB调试的方式去验证,结果每次全速运行暂停时,程序总停在中断里,中断入口函数如下所示,其中cnt是调试加的,当一直卡在中断里出不来时,会打印对应的中断号,果然这个中断号和EMAC的中断号是一致的。
voidgic_handle_irq(irq_regs_t*regs){uint32_tirqstat,irqnr;staticuint32_tcnt=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);#ifdefRT_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);#endifcontinue;}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的做法,将发送和接收的统计功能关闭,问题不再复现。