赞
踩
本文讲述一次spinlock死锁故障的定位过程,目的不在于问题本身,而在于展现一个内核bug的分析过程,提供一种分析思路,供大家参考。
一、问题现象
内核出现panic,kdump搜集到了vmcore。vmcore中直接导致panic的log信息为(包含相应CPU上的堆栈):
点击(此处)折叠或打开
二、问题分析
1、初步分析
内核出现异常,然后panic,必然会有相关直接原因的打印,本案例中如下:
Kernel panic - not syncing: Watchdog detected hard LOCKUP on cpu 18
结合内核代码分析,可以确认是由于nmi watchdog检测到了硬死锁(hard LOCKUP),nmi watchdog的具体原理不赘述了,可以google相关资料。
nmi watchdog检测到了硬死锁表明:该CPU核上发生了关中断死锁的情况。
根据其堆栈可以看到最终出现死锁的地方为_spin_lock_irq,即阻塞在关中断的spin_lock上,如果该锁一直获取不到,那就肯定是关中断死锁了,nmi watchdog自然就能检测到这种情况了,所以初步推断问题的直接原因是因为_spin_lock_irq一直获取不到锁导致死锁。
注意:这里的堆栈有一定的迷惑作用,咋一看wait_for_common,可能会以为该CPU是在等待complete变量的完成,但如果是这样的话,该进程应该是D状态,应该会调度出去,不会一直占用CPU,nmi_watchdog也不会触发。所以,需要看仔细。
2、深入分析
1)思维误区
接下来要分析为什么spinlock获取不到,这个问题要分析清楚,就比较复杂了。
通常来说,对于类似的死锁问题分析,都会有这种思路:死锁,那就肯定有进程持有相应的锁而一直不释放,导致本进程一直获取不到锁。
那就需要寻找持有锁的进程了,持有该锁的进程可能处于如下几种状态(按可能性大小排列):
a、处于RUNNING状态,且正在其它某CPU上运行。
b、处于RUNNING状态,但暂时没有得到调度运行。
c、处于D状态,等待某任务完成。
d、处于S状态
e、已经运行结束,进程已经不存在。
最可能的肯定是a和b,c、d和e属于明显的内核bug,对于c和d来说,因为spinlock持有者是不能sleep的,内核中对于持有spinlock再进行sleep的情况应该有判断和告警;对于e来说,那就是有进程持有spin_lock锁,但没有释放就退出了(比如某些异常分支),相当于泄露,这种情况内核中有静态代码检查工具,对于一般的用户态程序这种错误可能容易出现,但内核中这种可能性也极小。先不论可能性大小,对于本问题,这种想法将导致进入误区。照这种思路,分析过程大致为(这也是一种常用的分析思路,不能说不对,只能说不宜于本问题的分析):
(1)看看所有CPU上都在运行什么任务
点击(此处)折叠或打开
可以看出,出CPU3、18、19外,其它CPU都是阻塞在lock_kernel(大内核锁,老版本内核中,通常文件操作都需要持有大内核锁,对内核性能影响极大,新版本中已经逐渐去除)上,而CPU18正是触发nmi watchdog的CPU,其中的堆栈流程中可以看出,由ioctl进入,而ioctl的流程中正需要持有大内核锁:
点击(此处)折叠或打开
所以除CPU3、18和19外,其它的所有CPU都是因为CPU18而阻塞。
再看看CPU19,该CPU也阻塞在spinlock上,但是位于flush_tlb_others_ipi流程中,结合CPU3一起看,可以看出CPU3也是在这个流程中,但阻塞地方不一样(__bitmap_empty ),看看flush_tlb_others_ipi 的流程,可以确认__bitmap_empty是在获取spinlock后的流程了:
点击(此处)折叠或打开
于是可以确认,CPU19是因为CPU3而阻塞,那CPU3为什么阻塞呢?
再分析flush_tlb_others_ipi 和__bitmap_empty 的代码,可以知道flush_tlb_others_ipi是通过核间中断(IPI)让其它CPU flush自己的TLB,在更新页表或相关操作时会进行这样的操作。flush_tlb_others_ipi需要阻塞等待其它所有CPU都处理完相应的IPI并执行晚相关的任务(flush TLB)。而此时的CPU18(触发nmi watchdog的核)正处于关中断状态(_spin_lock_irq会关中断),所以其无法响应IPI,也就无法处理相关任务,所以导致CPU3一直阻塞了。
综上,可以看出,所有的CPU阻塞都是由于CPU18导致。于是经过这一轮,并没有找到持有spinlock不释放的进程,但毕竟还是理清了相关逻辑。
(2)于是再看看其它RUNNING状态的进程
crash> ps |grep RU|wc -l
838
800多个,有点奇怪,正常情况下不能这么多,否则这个机器性能可能面临严重问题了,但这个环境中所有CPU都锁死了,有很多没有得到调度RUNNING进程可能就正常了。这么多进程不能手工一个个看堆栈了,可以通过脚本处理:
crash> ps |grep RU|awk '{print $1}' > running_task_pid
Vim编辑running_task_pid文件,通过行模式插入一列bt (ctrl+v,大写I),然后再执行
crash> < running_task_pid > running_task_stack
搜集到所有RUNNING状态的进程堆栈后,通过分析,确认绝大部分进程的堆栈都在schedule中:
点击(此处)折叠或打开
应该是因为相关的进程被唤醒,但是一直没有得到调度,没有发现可疑进程。那就继续看看D状态进程的堆栈了
(3)查看所有D状态进程堆栈
crash> ps |grep UN|wc -l
46
逐个查看后,仍没有找到可疑进程。继续硬着头皮看看S状态进程的堆栈了?这个就没有太多意义了,因为即使是S状态进程获取到了该lock,但其堆栈很可能已经不在原来获取锁的上下文中了,堆栈中基本看不出来,另一方面也太多了,还是继续看看?用脚本。
(3)查看所有S状态进程堆栈
crash> ps |grep IN|wc -l
3056
再筛查一遍,还是没有看到可疑进程,进入了死胡同,无法继续了。获取可能会继续想,如果进程持有锁后退出了,也有这种可能,但这种情况已经无法通过vmcore来追溯了。
其实,本问题并不是之前想的那样,是因为锁被别人持有导致,如果我们一开始就以这种惯性思维来分析该问题,那最终就只能走到这里了,因为一开始就走错了路,主要问题还在于“没有从问题的最终现场出发”,“没有从问题的实质出发”,从某种角度上看,对于这种内核问题的分析,就跟刑侦警察分析刑事案件一样,最关键的是要“重视现场”,从案发现场寻找蛛丝马迹,如果没有现场,仅凭经验和推断,相信很多案件都无法侦破。
2)正确思路
从导致问题的最直接的现场出发
点击(此处)折叠或打开
因为 _spin_lock_irq 阻塞触发了nmi watchdog,看看相应的spinlock的具体的值:
点击(此处)折叠或打开
可以看出_spin_lock_irq的参数通过rdi传递(x86_64架构的传参规则,从左到右依次rdi、rsi...),而rdi在后续的函数中没有再使用,所以最终上下文中的rdi即为参数的值:ffff881054610960(bt中有RDI寄存器的值)
点击(此处)折叠或打开
可以看出该spinlock的值为00010001。
此版本中spinlock实现为ticket_spin_lock,大致原理如下:
4 字节的lock分成两部分:
Next(2字节)|Owner(2字节)
X86架构中,Next和Owner初始值都为0
在获取spinlock时,会对Next字段加1,然后判断加1之前的Next和Owner字段是否相等,如果相等,或获取锁成功,如果不相等,则nop后死循环再次获取Owner的值,一直到Next和Owner的值相等为止。
在释放spinlock时,会对Owner字段加1。如此当之前有进程在循环等待该spinlock时,在Owner加1后,就会因为Next==Owner而得到该锁,当之前有多个进程在等待该spinlock时,则最先进入等待状态的进程会先得到锁,这种机制能解决老版本spinlock机制中的“不公平”问题。
在初始状态下Next=Owner=0,此时如果有进程获取该spinlock,就可以得到该锁。
再看看该故障中lock的值:00010001,也就是说Next和Owner都等于1,说明已经lock和unlock一次了,看到这个值也许会觉得奇怪,此时Next和Owner相等,为何会获取不到锁呢?再看看出错的具体代码行:
点击(此处)折叠或打开
说明此时,已经进入到内联汇编所在的代码行了,此时的xaddl指令已经执行,Next已经加过1了,说明,在执行该_spin_lock_irq之前,该lock的Next值为0,而Owner的值为1,由于后续其它进程释放该lock时,只会对Owner进行加1,而此时Owner已经大于Next了(正常使用spinlock的情况下是不可能出现这种情况的),所以此时无论如何等待,Next也不可能等于Owner了,也就是说这里的锁永远也获取不到了,于是陷入了死锁状态。这样就可以解释为什么会在这里触发nmi watchdog了。
为什么会出现这种情况呢?Owner怎么可能大于Next呢?有两种可能:
1、多做了一次unlock操作
2、并发修改该spinlock。比如:在该spinlock还在被使用时,有其它进程并发修改该spinlock。更具体的例子:在CPU1上,某上下文进行spin_lock操作后,在spin_unlock之前;在CPU2上,另一上下文对该spinlock重新进行了初始化(即将该lock值改为0);然后在CPU1上执行unlock操作,此时该lock的Owner就被多unlock了1次,其Owner就被多加了1,就出现这种情况了。
对于第1种情况,出现的可能性极小,因为,spin_lock和spin_unlock操作肯定是配对的,内核中有相应的静态检查机制,也有相应的死锁检测机制,出现这种直接错误的可能性极小。
那最可能的原因就是因为情况2了。那就需要再仔细分析下问题出现的上下文(代码有4行错位,应该是vmlinux不匹配导致,但无大碍):
点击(此处)折叠或打开
_spin_lock_irq使用的spinlock为x->wait.lock,
继续看代码
点击(此处)折叠或打开
可以知道x是wait_for_completion_timeout传入的completion的结构体变量,看看该结构体的定义:
点击(此处)折叠或打开
而x是从mpt2sas驱动中的_ctl_do_mpt_command传入:
点击(此处)折叠或打开
看代码,ioc为MPT2SAS_ADAPTER结构体,该结构体定义在mpt2sas内核模块中,需要单独加载符号后,才能看到相关内容:
点击(此处)折叠或打开
需要继续分析这个completion的使用逻辑,在init_completion后,调用wait_for_completion_timeout等待该completion变量完成,即等待其它地方调用completion()函数来唤醒该进程。看起来逻辑没啥问题,但问题在于: 如果在调用init_completion之前,就有地方调用complete()函数的话,可能就有问题了,此时,如果另外的上下文刚好在lock之后unlock之前,就刚好符合之前说的情况2了。
分析mpt2sas驱动中可能调用这个completion的complete()函数的地方,仅在mpt2sas_ctl_done()和mpt2sas_ctl_reset_hangdler()中调用了,前者是在sas命令执行完成后调用的,其实就是_ctl_do_mpt_command中要等待的;而mpt2sas_ctl_reset_hangdler()仅在reset的时候使用,这里不用关注。
再看看_ctl_do_mpt_command的代码:
点击(此处)折叠或打开
在调用init_completion()之前调用了mpt2sas_base_put_smid_default,继续分析该函数的代码,发现该函数就是用于执行sas命令的,在命令执行完成后就可能走到mpt2sas_ctl_done()的流程,即在init_completion()之前,就可能先执行complete()函数了,由于mpt2sas_ctl_done()是异步流程(中断触发),完全可能在另外的CPU上执行,当命令执行比较快,在init_completion()之前就执行完了,就可能导致这样的问题了。
显然,这里的init_completion()应该放到前面更好。
google下相关的补丁,果然有相应的补丁:
点击(此处)折叠或打开
问题就此定位。
仔细想想,其实该问题的本质在于对completion结构的访问没有进行保护,由于可能在多CPU上并发访问,按理应该有相应的机制进行保护才对(比如锁),而这里没有,补丁中采用的方法是“串行化”,保证这种场景下的串行执行。但理论上应无法杜绝其它场景的并发,也许在mpt2sas驱动中没有其它的并发场景,其具体机制没有深入研究,不能妄下结论。
Copyright © 2003-2013 www.wpsshop.cn 版权所有,并保留所有权利。