性能文章>在调试里看 NV 驱动栈溢出导致的连环死锁>

在调试里看 NV 驱动栈溢出导致的连环死锁原创

4年前
975325

最近我使用的一台PC随机出现应用程序卡死。卡死的程序可能是VirtualBox虚拟机,可能是资源管理器,也可能是其它软件。有时是一个程序卡死,有时是几个程序卡死,甚至是卡死一大片,整个系统不能动弹,只好触发蓝屏,或者强按4秒,关机重启。

三次挂死

现在回想起来,第一次发生这个问题时,是在写一篇文章,正在收尾完工的时候,整个系统突然不能反应,屏幕全黑,但是老雷没有放弃,插了个USB键盘上去,过了一会,键盘居然有反应了(数字键盘锁定灯可以亮或者暗),于是老雷按下Ctrl + ScrollLock,触发蓝屏,虽然屏幕已经死了,没有显示,但是根据多年的经验,老雷感觉到了蓝屏是成功的,仿佛看到了那缕蓝光冲破黑暗,闪现出来…重启之后,真的发现有dump保存下来,说明老雷的感觉是对的。

第二次发生这个问题是在北京讲课,讲着讲着老雷兴起,想做个即兴的演示给大家看,没想到在搜索要启动的程序时整个系统卡死,突然的事故让老雷有点措手不及,赶紧解释了一下,然后趁课间休息的时间重启系统。

第三次发生是今天,一方面考虑到周五要做的公开课,另一方面考虑到,已经忍了两次,第三次不能忍了,是可忍孰不可忍:-)

这一次挂死的是WinDBG,老雷唤起它是要做内核调试的,目标机冻结,熟悉的int 3出现,一切顺利,但是WinDBG的命令行始终处于BUSY状态。

image.png

通常这样的等待是因为WinDBG在找符号,老雷用这个间隙倒茶。

但这一次,倒好茶还是BUSY,老雷意识到是“小鬼”出现了。

偷摸发信被卡牢

再启动一个WinDBG,附加到已经挂死的WinDBG上,~* k,先是看到调试引擎线程卡在一个关键区上:

   1  Id: e24.2fb8 Suspend: 1 Teb: 00000063`3def0000 Unfrozen

 # Child-SP          RetAddr           Call Site

00 00000063`3e2ff278 00007fff`3f43be9b ntdll!NtWaitForAlertByThreadId+0x14

01 00000063`3e2ff280 00007fff`3f43bd01 ntdll!RtlpWaitOnAddressWithTimeout+0x43

02 00000063`3e2ff2b0 00007fff`3f414571 ntdll!RtlpWaitOnCriticalSection+0x1a1

03 00000063`3e2ff360 00007fff`3f414490 ntdll!RtlpEnterCriticalSectionContended+0xd1

04 00000063`3e2ff390 00007fff`28b92d69 ntdll!RtlEnterCriticalSection+0x40

05 00000063`3e2ff3c0 00007fff`28b97ade sqmapi!AcquireSessionFromHandle+0x21

*** ERROR: Symbol file could not be found.  Defaulted to export symbols for C:\wd10x64\dbgeng.dll - 

06 00000063`3e2ff3f0 00007fff`03849482 sqmapi!SqmAddToStreamString+0x82

07 00000063`3e2ff440 00007fff`038fcbf0 dbgeng!Ordinal327+0x23ce2

08 00000063`3e2ff490 00007fff`038304bb dbgeng!Ordinal327+0xd7450

09 00000063`3e2ff520 00007fff`038307a3 dbgeng!Ordinal327+0xad1b

0a 00000063`3e2ffa10 00007ff6`57094948 dbgeng!Ordinal327+0xb003

0b 00000063`3e2ffa70 00007ff6`57093b1b windbg+0x34948

0c 00000063`3e2ffab0 00007ff6`57095419 windbg+0x33b1b

0d 00000063`3e2ffae0 00007ff6`5707c0c4 windbg+0x35419

0e 00000063`3e2ffb10 00007fff`3eb52774 windbg+0x1c0c4

0f 00000063`3e2ffba0 00007fff`3f470d51 KERNEL32!BaseThreadInitThunk+0x14

10 00000063`3e2ffbd0 00000000`00000000 ntdll!RtlUserThreadStart+0x21

观察这个管件区:

0:010> !locks

CritSec sqmapi!WPP_REGISTRATION_GUIDS+2298 at 00007fff28bc97d0

WaiterWoken        No

LockCount          1

RecursionCount     1

OwningThread       3520

EntryCount         0

ContentionCount    1

*** Locked

Scanned 31 critical sections

看来这个关键区是被3520线程捷足先登了,切到这个线程,观察:

  2  Id: e24.3520 Suspend: 1 Teb: 00000063`3def2000 Unfrozen

 # Child-SP          RetAddr           Call Site

00 00000063`3e37e538 00007fff`3cf32bf2 ntdll!NtAlpcSendWaitReceivePort+0x14

01 00000063`3e37e540 00007fff`3cfc9b61 RPCRT4!LRPC_BASE_CCALL::DoSendReceive+0x112

02 00000063`3e37e5f0 00007fff`3cfc85bd RPCRT4!NdrpClientCall3+0xa61

03 00000063`3e37ea30 00007fff`2d081090 RPCRT4!NdrClientCall3+0xed

04 00000063`3e37edc0 00007fff`28b9b829 SensApi!IsNetworkAlive+0x80

05 00000063`3e37ee20 00007fff`28ba965e sqmapi!IsNetworkAvailable+0xc9

06 00000063`3e37ee50 00007fff`28b983b8 sqmapi!CSqmHttpUploadManager::AddFilesToUploadQueue+0x7a

07 00000063`3e37f360 00007fff`038498e7 sqmapi!SqmStartUpload+0x1e0

08 00000063`3e37f3c0 00007fff`03849a5b dbgeng!Ordinal327+0x24147

09 00000063`3e37f830 00007fff`3eb52774 dbgeng!Ordinal327+0x242bb

0a 00000063`3e37f860 00007fff`3f470d51 KERNEL32!BaseThreadInitThunk+0x14

0b 00000063`3e37f890 00000000`00000000 ntdll!RtlUserThreadStart+0x21

从#7看,sqmapi!SqmStartUpload,是著名的遥感机制(Telemetry)试图往家里发数据(各位看官,可有读过老雷的“在调试器里看Windows 7发信回家”)。

从IsNetworkAlive看,是在发信之前判断是否有网络。但这个看似简单的问题其实不是那么容易,于是利用RPC发起远程调用。

我们暂不评论偷摸发信是否合理,还是继续追踪为啥判断是否联网这点小事就能把骁勇的WinDBG卡死?

寻找RPC的服务端

又是RPC,仍使用上次的方法,使用本地内核调试找到3520线程,可以看到它真的在等待RPC回应。

THREAD ffffcb008241c080  Cid 0e24.3520  Teb: 000000633def2000 Win32Thread: 0000000000000000 WAIT: (WrLpcReply) UserMode Non-Alertable

            ffffcb008241c6c8  Semaphore Limit 0x1

        Waiting for reply to ALPC Message ffff8a8281d7b650 : queued at port ffffcb007146c6e0 : owned by process ffffcb00713c2640

        Not impersonating

        DeviceMap                 ffff8a8283d9b630

        Owning Process            ffffcb0082fa2640       Image:         windbg.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      3574818        Ticks: 89602 (0:00:23:20.031)

        Context Switch Count      7              IdealProcessor: 1 

观察服务进程:

lkd> !process ffffcb00713c2640 0

PROCESS ffffcb00713c2640

    SessionId: 0  Cid: 07c8    Peb: 93377db000  ParentCid: 033c

    DirBase: 11145b000  ObjectTable: ffff8a827e09d340  HandleCount: 199.

    Image: svchost.exe

原来是svchost,根据进程ID(7c8,即1992)到服务列表里查找,可以知道它是“系统事件通知服务” System Event Notification Service (SENS)
image.png

SENS机制是有文档的,MSDN很详细。
image.png

探索SENS服务

接下来观察SENS服务进程的情况,特别注意WinDBG所调用RPC的服务线程(通过!alpc -m消息可以知道)。

结果让人吃惊,和上次微信的例子有点类似,又是连环的RPC,这个服务线程又发起RPC了,在等待回复。

THREAD ffffcb0081b95040  Cid 07c8.1dc0  Teb: 000000933765c000 Win32Thread: 0000000000000000 WAIT: (WrLpcReply) UserMode Non-Alertable

            ffffcb0081b95688  Semaphore Limit 0x1

        Waiting for reply to ALPC Message ffff8a827dcca040 : queued at port ffffcb007f2d0890 : owned by process ffffcb007e967080

        Not impersonating

        DeviceMap                 ffff8a826f602090

        Owning Process            ffffcb00713c2640       Image:         svchost.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      3658023        Ticks: 456617 (0:01:58:54.640)

        Context Switch Count      237            IdealProcessor: 2             

        UserTime                  00:00:00.000

        KernelTime                00:00:00.000

        Win32 Start Address ntdll!TppWorkerThread (0x00007fff3f4412c0)

        Stack Init ffff9e01ddd7fc10 Current ffff9e01ddd7f3c0

        Base ffff9e01ddd80000 Limit ffff9e01ddd79000 Call 0000000000000000

        Priority 8 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5

        Kernel stack not resident.

它为啥要发起RPC呢?可以再挂一个调试器在SENS服务上观察。

image.png

从#0a看,上面这个线程真的是在处理WinDBG发起的网络是否可用的请求,执行的函数是sens!RPC_IsNetworkAlive。但是这个问题,对于它来说也不能做主,要继续调用RasApi32!RasEnumConnectionsW。这个函数是有文档的:

DWORD RasEnumConnections(
  _Inout_ LPRASCONN lprasconn,
  _Inout_ LPDWORD   lpcb,
  _Out_   LPDWORD   lpcConnections
);

不过我们不想读,因为从栈上来看,它内部又发起了RPC,与我们在内核态看到的结论是一致的。

RAS服务

从函数名可以看出,SENS服务调用的是RAS服务。有了这个信息可以从服务列表里找RAS服务,也可以继续用我们的内核调试会话找。无论哪种方法,结论都是,SENS服务调用的是进程ID为3488的svchost进程。

再开一个WinDBG(上调试器),以非入侵方式附加到3488进程,~* k观察。立刻发现了特殊情况:第31号线程的栈帧特别多,显示的很长,而且感觉还没有显示完整。

切换到31号线程,k 2000。用了几十秒,才显示完毕,一共有3130(c3a)个栈帧。

根据老雷的经验,这样疯狂的调用,很可能把栈用光了。

观察寄存器现场:

0:031> r

rax=0000000000000001 rbx=00007fff03fb3060 rcx=000000046db83f10

rdx=0000000000000000 rsi=000001fd79f640a0 rdi=000000046db84140

rip=00007fff03fb3103 rsp=000000046db83ee0 rbp=000000046db83fe0

 r8=0000000000000180  r9=000000046db84404 r10=0000000000000004

r11=000000046db840c8 r12=0000000000000001 r13=000001fd78a82c30

r14=0000000000000000 r15=0000000000000000

iopl=0         nv up ei pl zr na po nc

cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00010244

D3D12!NDXGI::CDevice::SubmitCommandCB+0xa3:

00007fff`03fb3103 e8f07b0200      call    D3D12!memset (00007fff`03fdacf8)

显示栈指针附近的内存:

0:031> dd 000000046db83ee0 

00000004`6db83ee0  00000000 00000000 00000000 00000000

可以显示,说明栈上有可用内存。
但是从内核态观察这个线程,明明是有异常发生了。

image.png

这是怎么回事呢?

听过老雷课的或者认真读过《软件调试》的,或许已经想出了原因。
用户态的栈式可以自动增长的,一般是先保留1MB,提交一点点,提交部分上面放一个保护页,用完了就会碰到保护页,于是再提交。

但是这个过程不是无止境的,在32位时,当栈的保护页已经到了保留的最后一个页时,保护页无处可移,系统这时会发出栈溢出异常,通知应用程序,栈要用完了。

观察31号线程的栈,果然已经没有保护页了(带PAGE_GUARD属性)。
image.png
看来真的是栈溢出了。

谁用光了栈

那么是谁用光了栈空间呢?浏览k命令的结果,很容易看出答案,名为nvwgf2umx_cfg的模块似乎陷入了死循环,反复调用数千次:

image.png

这个模块是谁家的呢?nv啊!GPU时代的一号公司。

image.png

看文件日期,还是很新的文件。

辕门失火

那么RAS服务内部为什么要调用NV的模块呢?浏览31号线程的栈帧,看它为何发起长调用。

image.png

发起模块是wuaueng,微软给出的大名叫Windows Update Agent,全称或许为Windows更新自动引擎。

从下面的这些栈帧来看,自动更新引擎是在努力的找活干(FindUpdates),从服务器那边拿到信息后评估在本机的适用性(EvaluateUpdateApplicabilityRules),规则似乎挺复杂的,支持表达式,在评估表达式时,先调用了D3D接口,而后转到了NV的驱动模块。

c1d nvwgf2umx_cfg!OpenAdapter12

c1e nvwgf2umx_cfg!OpenAdapter12

c1f nvwgf2umx_cfg!OpenAdapter12

c20 nvwgf2umx_cfg!NVENCODEAPI_Thunk

c21 nvwgf2umx_cfg!NVENCODEAPI_Thunk

c22 D3D12!NDXGI::CDevice::CreateDriverInstance

c23 D3D12!CDevice::LLOCompleteLayerConstruction

c24 D3D12!NDXGI::CDevice::LLOCompleteLayerConstruction

c25 D3D12!D3D12CreateLayeredDevice

c26 D3D12!D3D12CoreCreateLayeredDevice

c27 D3D12!D3D12CoreCreateDevice

c28 D3D12!D3D12CreateDeviceImpl

c29 D3D12!D3D12CreateDevice

c2a wuaueng!Direct3DEvaluator::GetMaxSupportedD3D12FeatureLevel

c2b wuaueng!Direct3DEvaluator::EvaluateFeatureLevel

c2c wuaueng!CSystemExprEvaluator::EvaluateDirect3D

c2d wuaueng!CSystemExprEvaluator::Evaluate

c2e wuaueng!CBaseEEHandler::Evaluate3

c2f wuaueng!CExprElementTreeNode::Evaluate

c30 wuaueng!CAgentUpdateManager::EvaluateUpdateApplicabilityRules

c31 wuaueng!CAgentUpdateManager::DetectForUpdate

c32 wuaueng!CAgentUpdateManager::EvaluateUpdateSet

c33 wuaueng!CAgentUpdateManager::DetectForUpdates

c34 wuaueng!CAgentProtocolTalker::SyncServerUpdatesInternal

c35 wuaueng!CAgentProtocolTalker::SyncServerUpdates

c36 wuaueng!CAgentUpdateManager::FindUpdates

看来是自动更新逻辑引发了NV模块的疯狂逻辑。两个逻辑可能没有磨合太好。一个说“兄弟你啥版本啊,需要更新不”,“另一个说,更新更新,整天更新个锤子啊”,一言不合,索性把栈用光。哈哈,结果大家都动不了了。

那么自动更新增么和RAS扯到一起的呢?

它们本来真的没有一毛钱关系。只是租房子的时候住到了一起,就为了节约点开销啊。

image.png

这样分析下来,可以比较确定的说,随机卡死案件的起因是有人检查网络是否可用(IsNetworkAvailable),RPC调用先是到了SENS服务,又到了RAS服务。在调用时,不想刚好遇到与RAS服务合租的WUAU服务屋里“起火”,更新引擎的表达式平谷逻辑调用NV的驱动模块,后者把栈用完,导致整个进程被挂起,于是RAS和WUAU都动不了了,SENS服务卡住了,调用者也卡住了。

这个结论与曾经分析过的微信挂死颇为类似,结论都与第三方驱动相关。上次是MaxxAudio,这次是大名鼎鼎的NV…

点赞收藏
张银奎

前英特尔软件架构师

请先登录,查看2条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

JDBC PreparedStatement 字段值为null导致TBase带宽飙升的案例分析

JDBC PreparedStatement 字段值为null导致TBase带宽飙升的案例分析

服务器之 ECC 内存的工作原理

服务器之 ECC 内存的工作原理

随机一门技术分享之Netty

随机一门技术分享之Netty

从 Linux 内核角度探秘 JDK MappedByteBuffer

从 Linux 内核角度探秘 JDK MappedByteBuffer

MappedByteBuffer VS FileChannel:从内核层面对比两者的性能差异

MappedByteBuffer VS FileChannel:从内核层面对比两者的性能差异

日常Bug排查-连接突然全部关闭

日常Bug排查-连接突然全部关闭

5
2