【内核】【转载】记一次Linux Hung Task分析过程

vmcore-dmesg.txt截图如下,崩溃栈里面有我们产品的驱动,现在要分析出是不是我们导致的。系统崩溃是因为触发了hung task检测条件,系统panic了。所谓hung task,就是进程的状态为D状态,即TASK_UNINTERRUPTIBLE状态,短时间的D状态是正常的,长时间就会有问题了,可能系统IO有问题,也可能其他bug导致。

img

直接分析vmcore,先看下有哪些进程是D状态:

img

有5个进程是D状态,不清楚是哪个进程D状态导致的,又看了下vmcore-dmesg.txt,触发hung task检测条件的进程为1号进程,看下1号进程的调用栈:

img

从这个调用栈大概可以知道,1号进程(systemd)调用rmdir删除某个文件夹(系统调用号0x0000000000000054,RAX值)时,在内核态等待完成(wait_for_completion)时,系统长时间没有完成并唤醒该进程。首先大概分析看看是删除什么文件夹,根据64位系统调用原理,RDI寄存器里面的地址存储了应用层的文件路径,先获取对应的物理页:

img

物理页(PAGE)是a2c570,但是很遗憾,这个系统开启了swap,这个应用层物理页已经被swap out了,没法读取里面的内容,那只能在内核态栈里面找找了。

img

查看do_rmdir代码,在代码开始的地方,有几个局部变量name、dentry、nd。这几个变量里面应该都存储了路径相关的信息,但是这些变量不一定会保存在栈里面,有可能是保存在寄存器里面,这个需要结合汇编代码去分析,通过dis do_rmdir,找到call user_path_parent的地方,这个函数返回值是name,保存在rax寄存器中,我们发现汇编里面是直接使用的rax,并没有保存到栈里面,因此,我们无从知道name的内容;user_path_parent这个函数有四个参数,分别使用rdi,rsi,rdx,rcx传递,rdx中即保存了nd的地址,那rdx里面的地址是怎么来的呢,上图红框里面的那条汇编指令就是给rdx赋值:lea 0x10(%rsp),%rdx,即把rsp+0x10的地址赋给了rdx,换句话说,rsp+0x10的地方就是nd的起始地址。bt -f 1看下do_rmdir的栈帧:

img

vmcore里面的do_rmdir的rsp是ffff8835b948fd58这个地址,但是这个时候应该是do_rmdir里面call了vfs_rmdir了,因此,在调用user_parent_path的时候,rsp应该是ffff8835b948fd60(后面只有call,没有push了),所以nd的地址为ffff8835b948fd70(ffff8835b948fd60+0x10),我们用这个地址看下nd里面的内容:

img

可以看到,是在删除一个名为sysstat.service的目录,不过这里只是last name,不是完整的路径,完整的路径还需要结合mnt和dentry去向上回溯,mnt和dentry也同样保存在nameidata里面。这里我就不继续分析到底是哪个完整路径了。

现在已经清楚,systemd 1号进程调用rmdir删除sysstat.service目录时,卡住了,至于为什么卡住,我们下面继续分析。还是回到systemd的内核栈帧上,从调用栈可以看出,do_rmdir里面调用了vfs_rmdir,vfs_rmdir里面调用了cgroup_rmdir,这个cgroup应该是和docker相关的技术,在cgroup_rmdir里面,最终调用了flush_work后,调用wait_for_completion等待完成,但是一直未能等待到,从而导致了panic。flush_work这个和Linux内核的工作队列有关,工作队列是Linux内核中异步执行的一种机制,用于延迟执行一些需要在进程上下文中执行的任务,而flush_work是需要等待work执行完成,才继续向下执行,相当于把异步变成了同步。

bool flush_work(struct work_struct *work)
{
        //
	// struct wq_barrier {
	// struct work_struct	work;
	// struct completion	done;
        // };
	//  wq_barrier有work信息,又有completion信息,既能执行work,又能等待完成
	struct wq_barrier barr;

	lock_map_acquire(&work->lockdep_map);
	lock_map_release(&work->lockdep_map);

	// start_flush_work主要就是设置barr的逻辑
	if (start_flush_work(work, &barr)) {
	    // 等待,在这里面设置为D状态然后schedule,等待被唤醒,120s未被唤醒
		wait_for_completion(&barr.done);
		destroy_work_on_stack(&barr.work);
		return true;
	} else {
		return false;
	}
}

flush_work主要逻辑是在start_flush_work里面:

img

start_flush_work里面主要就是get和insert,最终会调用wake_up_process去唤醒对应的kworker线性去执行worker,所有的数据和结构都会保存到flush_work函数里面的barr这个栈变量中,如果知道了barr的地址,就可以知道最终是唤醒哪个kworker去执行的。

img

结合反汇编和源码,可以看到,rbp-0x68的地址即为barr的地址

img

那么flush_work的rbp地址是多少呢,上图所示,ffff8835b948fbf0这个地址是call flush_work自动压入的,此时rsp即为ffff8835b948fbf0,flush_work里面,先push了rbp,然后又mov rsp rbp,所以,rbp是ffff8835b948fbe8,即ffff8835b948fbf0-0x8,所以wq_barrier的地址为ffff8835b948fb80(ffff8835b948fbe8-0x68),看下里面的内容:

img

可以简单验证下找到的是否正确,这个结构里面有个func的函数指针,根据代码,这个函数指针指向了wq_barrier_func这个函数,看下我们获取的结构里面func是否为wq_barrier_func。

img

是一致的,于是可以确认找到的wq_barrier的地址是正确的,于是我们顺着wq_barrier->data这个藤,最终找到了worker这个瓜:

img

最终我们从woker里面找到了那个kworker线程,task为0xffff8835b886af70

img

这个kworker的名为kworker/3:2,也就是绑定在CPU3上的一个内核线程,这个线程从栈来看,还是一个被调度出去的状态,但是线程的state已经是RUNNING了,那就是说,这个线程已经被唤醒加入到runqueue等待执行了,通过runq命令看下执行队列的排队情况:

img

可以看到,kworker/3:2已经就绪,就等着前面的线程执行完成了,而当前正在执行的这个lo开头的线程是一个其他厂商的一个内核线程,有没有可能是这个线程某个原因死循环了,一直在跑,导致后面排队的线程得不到执行机会呢。

img

可以看到,这个线程确实有问题,占用了1038秒的CPU时间,但是只主动切换了1次,也就是说,这个内核线程一直在跑,基本就没有退出过,不过这种情况应该会导致soft_lockup才对,为啥vmcore-dmesg.txt里面没有呢,这个需要看下当前环境上softlockup的配置了,通过sysctl -a|grep watchdog以及sysctl -a|grep softlock可以看到,kernel.watchdog已经关闭,难怪没有能产生soft_lockup日志。如果开启的话,系统早就因为这个内核线程softlockup而panic了,根本不会因为这个问题再引出一个hung task的问题。至此,问题分析清楚,需要客户联系该厂商排查。

原文链接:https://zhuanlan.zhihu.com/p/691542282?utm_campaign=shareopn&utm_medium=social&utm_psn=1782729650826387458&utm_source=wechat_session

posted @ 2024-10-07 21:37  学习,积累,成长  阅读(48)  评论(0编辑  收藏  举报