近期在处理cpu soft lockup问题时注意到rpciod进程影响较大,先简单了解下,具体还未找到原因和解决方法
rpciod进程简介
rpciod进程对应的内核线程共有32个,从rpciod/0到rpciod/31(具体查询见下图), 每个处理器核对应一个rpciod内核线程,主要作用是作为远过程调用服务的守护进程,用于从客户端启动I/O服务,通常启动NFS服务时要用到它。
rpciod问题报错
通过messge日志看到,cpu soft lockup产生,导致软锁的进程名字和PID为:rpciod进程,PID 5562,所在的cpu逻辑核为cpu0上,软中断67s。
kernel: BUG: soft lockup - CPU#0 stuck for 67s! [rpciod/0:5562]
截图如下:第一行信息。
分析过程
通过接下来的trace call堆栈调用信息分析和sunrpc模块对应的NFS服务有关。
kernel: Call Trace:
kernel: <IRQ>
kernel: [<ffffffff814e2033>] ? packet_rcv+0x373/0x440
kernel: [<ffffffff81448167>] ? __netif_receive_skb+0x477/0x750
kernel: [<ffffffff8144a578>] ? netif_receive_skb+0x58/0x60
kernel: [<ffffffff8144a680>] ? napi_skb_finish+0x50/0x70
kernel: [<ffffffff8144cc29>] ? napi_gro_receive+0x39/0x50
kernel: [<ffffffffa018526c>] ? igb_poll+0x7ec/0xc70 [igb]
kernel: [<ffffffff8100de89>] ? handle_irq+0x49/0xa0
kernel: [<ffffffff81076d58>] ? irq_exit+0x48/0x90
kernel: [<ffffffff81516c95>] ? do_IRQ+0x75/0xf0
kernel: [<ffffffff8144cd43>] ? net_rx_action+0x103/0x2f0
kernel: [<ffffffff81076fb1>] ? __do_softirq+0xc1/0x1e0
kernel: [<ffffffff8100c1cc>] ? call_softirq+0x1c/0x30
kernel: <EOI>
kernel: [<ffffffff8100de05>] ? do_softirq+0x65/0xa0
kernel: [<ffffffff810778fa>] ? local_bh_enable_ip+0x9a/0xb0
kernel: [<ffffffff815101ab>] ? _spin_unlock_bh+0x1b/0x20
kernel: [<ffffffffa03b1a4c>] ? xprt_release+0xac/0x220 [sunrpc]
kernel: [<ffffffffa03b8f5d>] ? rpc_release_resources_task+0x1d/0x50 [sunrpc]
kernel: [<ffffffffa03b9a84>] ? __rpc_execute+0x174/0x350 [sunrpc]
kernel: [<ffffffffa03b9d00>] ? rpc_async_schedule+0x0/0x40 [sunrpc]
kernel: [<ffffffffa03b9d2a>] ? rpc_async_schedule+0x2a/0x40 [sunrpc]
kernel: [<ffffffff81090ac0>] ? worker_thread+0x170/0x2a0
kernel: [<ffffffff81096c80>] ? autoremove_wake_function+0x0/0x40
kernel: [<ffffffff81090950>] ? worker_thread+0x0/0x2a0
kernel: [<ffffffff81096916>] ? kthread+0x96/0xa0
kernel: [<ffffffff8100c0ca>] ? child_rip+0xa/0x20
kernel: [<ffffffff81096880>] ? kthread+0x0/0xa0
kernel: [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
关键词分析:autoremove_wake_function、rpc_async_schedule、rpc_execute、rpc_release_resources_task、xprt_release、spin_unlock_bh、local_bh_enable_ip、do_softirq、接下来的call_softirq、net_rx_action、do_IRQ、irq_exit、handle_irq、napi_gro_receive、netif_receive_skb、packet_rcv。
从上面的关键词判断:rpc在调用执行过程(autoremove_wake_function、rpc_async_schedule、rpc_execute、rpc_release_resources_task等)中引起了softirq(软中断)导致了net模块异常,引起了相应网络的短暂性中断(soft lockup--67s)。
具体rpciod调用过程出现的日志报错需要通过kdump功能的vmcore日志(故障时黑匣子)分析具体发生了什么,比如rpciod的多长事件引起IRQ函数中断,导致了cpu soft lockup现象产生。
其他分析
通过对rpciod进程分析后,发现正真反应到系统内具体服务的时NFS服务,具体排查过程如下:
ps aux | grep rpciod 查看当前系统中rpciod进程运行时间,从截图中发现rpciod进程ID 5562对应的时间较长,对应的cpu核为0。
可以通过挂载关系和磁盘使用关系找到nfs的详细信息。
比对其他未发现cpusoft lockup的主机系统,rpciod对应的信息(系统运行时间为0,表示没有堵塞)如下: