Win32K里的死循环

引用注明>> 【作者:张佩】【原文:www.YiiYee.cn/blog

这是我到新公司后上手的第一个issue。一线工程师找到我,说有一个urgent issue有没有兴趣看一看。当时他已经组织了一个team的人帮助他,我便成了其中一员。

问题确实很紧急,已经影响了产线的生产。当时正临清明假期,导致很多人都岌岌可危地面临清明加班的可能。其实这个问题已经报出来好几个月,但一线工程师一直以绥靖政策对待,以各种方式把问题发生率降低到客户接受的水平。绥靖政策长时间以来是有效的,但最近却突然失效,发生率飙升到了20%。一线工程师才真的着急了。

问题定性

组一个team的人debug同一个问题,在我以前是未曾经历过的。初始的想法当然是认为人多力量大。但真正实施的时候,也可能遭遇人多嘴杂的窘况。

在如何定性issue的问题上大家意见不一致。从一线工程师描述的情况看,问题发生时没有蓝屏。先前曾debug过此问题的同事说,问题发生时只有一个进程和线程活着,其它的所有进程都处于block状态(除了idle进程);最关键的是,他仍然可以通过Windbg单步。

有人把issue定性为系统崩溃、BSOD或系统异常,这是完全不正确的。如果被这样定性,CPU必须是hang住的。但现在CPU却是活的,还可以单步。况且并没有蓝屏发生,定性为BSOD就更不对了。

应该属于什么类型的问题呢?从描述上来看,系统是活的,只是失去了响应而已。所以我把issue定性为系统的Software Hang。可能的情况很多,比如一个系统进程突然跑偏了,导致系统界面失去响应。或者像本例中的情况:系统内核自己陷在一个死循环里面,无暇处理其它任务。

分析问题

我第一天只拿到了dump文件。因为只有一台能live debug的系统,使用上很难统筹。我拿到dump文件后,第一动作是赶紧看那个唯一live的线程。这类issue的问题点非常集中,所以我很有把握可以很快找到一些有用线索。

ChildEBP RetAddr  Args to Child              
85846dd0 8fd95b75 ffffffff 85846ef0         nt!KeClockInterruptNotify+0x28a 
(Inline) -------- -------- -------- --------     hal!HalpTimerClockInterruptEpilogCommon+0xa
85846de0 00000000 000000d1 00000000 hal!HalpTimerClockInterruptCommon+0x3e 
85846de0 00000000 000000d1 00000000 hal!HalpTimerClockInterrupt+0x1cb 
85846ef0 80c66050 8584762c 00000002 win32k!ENUMAREAS::ENUMAREAS+0xb9 
8584711c 80da5d98 80da5d98 00000000 win32k!bSpBltScreenToScreen+0x2f8 
858474dc 80da5d98 80da5d98 00000000 win32k!SpBitBlt+0x2bc
85847510 80da5d98 80da5d98 00000000 win32k!SpCopyBits+0x27
85847654 000006ce 000000a0 00000027 win32k!NtGdiBitBltInternal+0xa39
85847700 80d440a8 80c7d5e0 80c7d598 win32k!zzzBltValidBits+0xc6557 
85847768 85847b18 85847ad0 80dac008 win32k!xxxEndDeferWindowPosEx+0x20b
858477a8 00000000 8312c5a0 80dac008 win32k!xxxProcessDesktopRecalc+0x10b
858477e0 d4b8b27d 85847d00 80dac008 win32k!xxxProcessEventMessage+0x7a
……
85847d3c 0118fb90 00000000 00000000 nt!KiSystemServicePostCall

调用栈上面有时钟中断的处理函数。当硬件中断发生的时候,CPU会亲自把当前活动线程的执行权抢占下来给ISR用。所以这是很正常的事情。并不是发生了所谓的“系统异常”。去掉中断相关处理函数后,调用栈的最后一个函数就是win32k!ENUMAREAS::ENUMAREAS

我把这个函数的汇编代码略微研究了一下,发现这里面竟然存在一个死循环!当然,不是所有的循环都天生会成为“死循环”。死循环只可能发生在特殊的状态下。从汇编代码看,Win32k正执行在一个循环中。这个循环只会进入一次。同事给我提供了一个有用信息:每次问题发生的时候,看到的都是在执行同一个函数。结合这些信息,当然就可以断定这个循环是“死循环”了。

但当我把这个发现提出来准备team内讨论时,却受到了冷遇。没有人相信或愿意和我讨论这个死循环。debug team的一位同事没看分析过程,但把同一个问题问了我两遍:你真有把握这是死循环吗?令我非常郁闷。

第二天当Live Debug环境再次被建立起来,我能亲自上手的时候,我就首先在这个函数里面单步了好一会儿,确定它确实是在我发现的那4行汇编代码里面循环不止的。事实证明,不管我按多少次F10,指令寄存器都再没有离开过那4行汇编代码(除了发生时钟中断抢占的情况)。我当时心里立刻舒缓了很多,因为我还是很害怕的,万一不是死循环,就颜面扫地了。

死循环的逻辑很简单,只有4行汇编。两个跳转(jump)语句在互相跳来跳去,是一个典型的while循环。

901b7b0f   394104         cmp     dword ptr [ecx+4],eax
901b7b12  7e5e             jle        win32k!ENUMAREAS::ENUMAREAS+0xb6 (901b7b72)

901b7b72  034908         add      ecx,dword ptr [ecx+8]
901b7b75  eb98             jmp     win32k!ENUMAREAS::ENUMAREAS+0x53 (901b7b0f)

花几分钟时间把这4行代码反汇编成C语言,因为这时候我们已经有了win32k的private symbol,所以反出来的内容可读性很强。

while (p->yBottom <= this->yBoundsTop)
{
     (char*)P += p->sizeScan;
}

这是一个普通的循环。但如果循环体里面的p->sizeScan值为0,就能导致死循环。这正是原因所在。

猜猜猜

每个资深Debug工程师都有一样本领,那就是“猜”。闭源调试的时候,“猜”是不二利器。当然了不能乱猜,否则会导致怨狱的——不能变成猜疑。

我发现当死循环发生时,yBottom的值是1200,yBoundsTop的值是1780。我对1200非常敏感,因为目标平台的分辨率是1800×1200。再加上通过private symbol展现出来的变量名称,更增加了猜的底气。所以就先猜1200是屏幕的高。

1780是什么呢?结合Win32k类的名称ENUMAREAS以及变量名称yBoundsTop,猜它是某个窗口的左顶点y轴位置。

继续猜。再仔细看调用栈中各个函数的名称,可以大致知道它在干什么:通过GDI接口实现BitBlt亦即画图操作。

现在基本给出一个合理猜想:问题发生的时候,有一个窗口被移出了屏幕以外区域,当这个窗口试图刷新UI界面时,有概率会导致Win32K的死循环。

下一步是根据上述合理猜想,给出一个解决方案:测试过程中,避免一切移动窗口位置到屏幕外的动作。

一线工程师在了解了这个情况后还不放心,在解决方案中又加了一条:避免一切窗口最小化动作。

当这个方案报告给客户后,客户立刻进行了测试,在上千次测试过程中,问题再也没有发生。并且,到现在为止的一个多月时间里,issue再也没有发生。

技术细节

当事实确定下来后,大家都非常惊讶。因为win32k是一个非常稳定的OS模块,如果真是win32k的bug,其影响一定非常地深远。这个问题现在已经报告给微软,微软工程师还在分析,并已承认是系统Bug的事实。但微软工程师更倾向于认为这不是Win32k的bug,而是传给Win32K的参数被破坏了。最后的结果如何,还需等待。

如果我是这位微软工程师,我就会把这个调用栈上相关函数的实现逻辑,先好好地分析一遍。对照出问题和正常情况下的参数差别,区别出此issue是由代码逻辑导致的,还是异常参数导致的。如果是异常参数导致的,需确定是参数传入时就有问题,还是后面出的问题。以此逐步厘清。

while (p->yBottom <= this->yBoundsTop)
{
     (char*)P += p->sizeScan;
}

其中this的类型为ENUMAREAS,其部分定义如下:

win32k!ENUMAREAS
   +0x000 iDir               
   +0x004 xBoundsLeft           
   +0x008 yBoundsTop            
   +0x00c xBoundsRight         
   +0x010 yBoundsBottom

p指向的结构体为SPRITESTATE,其前面部分定义如下:

_SPRITESTATE
 +0x000 yTop
 +0x004 yBottom              
 +0x008 sizeScan

我分析认为:p指向一个类型为SPRITESTATE的变长结构体数组,其中变量sizeScan表示到达下一个结构体的长度。当问题发生时,p已经枚举到了数组中的最后一个结构体,其成员变量sizeScan等于0。因为这个循环缺少了异常处理,从而使得p一直在处理最后一个结构体,在它身上做死循环,并奇怪地把整个系统都hang住了。当我通过Windbg强制跳出这个死循环后,系统奇迹般地活了过来。

6,735 total views, 2 views today

《Win32K里的死循环》有9个想法

    1. Superbe idée. Plus de problème pour ceux qui apprehendent la plongée et de découvrir les fonds marins à la façon du Capitaine Némo…..A quand les investissements dans les résidences « sous la mer », attention il faudra bien réfléchir à toutes les conséquences que cela ennisinera.Pasarontement. A suivre…lefertois

  1. 闭源debug真的很需要经验,不得不佩服你。我会想,如果是我遇到了这个问题,我该怎么分析,我觉得我不会也不敢往Win32的死循环这个方向想,在我心里面我有点太相信微软了。。。

  2. “我把这个函数的汇编代码略微研究了一下,发现这里面竟然存在一个死循环!” 想请教一下怎么研究汇编代码的?具体都用到哪些命令?谢谢

  3. 如果要进上步探究最终的原因,还需要实验设计,重现问题。如果可以通过实验的方法,重现场景,并取得数据作为证据,就能准确地定位问题。然后从源码的角度,从逻辑的角度,理解问题发生的过程,就圆满了。除了探究,没有多少人肯真正地这样做,因为这需要投入很多时间。

水水进行回复 取消回复

电子邮件地址不会被公开。