子子翔的专栏

挨踢民工生涯

第一次遇到死锁——记一次程序卡住问题的错误排查过程

10月24日,周四


  我负责的游戏启动程序(Launcher)更新上线后,临下班前接到运营消息,反映部分网吧启动Launcher后无反应。跑到客服现场,通过QQ远程桌面观察到如下现象:双击程序图标后,程序出现在任务管理器进程列表里,但无任何其它反应,没有任何界面弹出;然后程序就一直这样无任何响应,只能在任务管理器中把进程杀掉。


  于是在现场通过Process Explorer抓出几个dump——任务管理器中没有转储dump的选项,只好用Process Explorer抓。这些dump均显示程序卡在了WinVerifyTrust这个Windows API上,即卡在了数字签名验证上。

  由于之前已经有过WinVerifyTrust响应慢的经验(只是技术总监表示这种情况不会在外网发生),我当即发信给所有相关人员(包括运营产品部负责人B、项目制作人J和技术总监等),说明情况,询问是否要立即把WinVerifyTrust放到另一个线程,并提供紧急修复。


  J否定了我的思路。他没有清楚地说明为什么我的思路不对,只是问改成多线程会有什么后果。我想可能是因为我给出的原因不具有说服力,没说出为什么会卡在数字签名上,且我的解决方案也只是规避,并没有从根本上解决问题。同时B表示没理解我的意思,且这次更新所对应的代码改动和数字签名毫无关系,之前也没出现过这种卡在数字签名上的现象。

  J在公司附近找到了一家能稳定重现该问题的网吧。于是下班后我们俩在那家网吧一直待到半夜12点,在现场研究这个问题。期间J还跟我谈到了看现场的重要性。我们公司另一个网游项目曾经遇到过一个问题:部分网吧的游戏客户端没有声音。项目团队研究了几个月都没有进展。后来J在北京探亲时正好路过一个能重现该bug的网吧,进去研究了一番,发现客户端一配置文件有问题,这是由网吧硬盘的不可写导致的。他立即将此事告知该项目的制作人,于是bug很快得到修复。

  回到我们Launcher的问题。在网吧的研究结果如下:


  1、我们是10月23日同步并推送的程序,但网吧里的程序文件的修改日期是9月24日。不过查看这些文件的数字签名,发现仍是10月23日,且数据文件中记录的版本号已是最新,说明10月23日确实向网吧推送过版本。因此我们首先有一个猜测:会不会是运维错误地推送了老的版本。然而,此结论不能解释为什么无法启动的现象只在部分网吧出现;而且我发现我们新加的一个功能已经出现在那个网吧的客户端中,这个现象更是与我们的猜测矛盾。


  2、考虑到我的程序经过加壳加签名才会发布到线上,因此我又跑回公司,重新编译了一个未加壳未加签名的exe拿去该网吧继续测试。结果该exe在该网吧却能正常运行,似乎可以初步确定该问题与加壳或数字签名有关。


  我本打算在网吧现场抓几个dump,进行现场调试,但没想到Process Explorer竟然无法在网吧里运行,一启动就会报错,估计是没有权限。因此决定等第二天和运维部门沟通,确认版本是否正确。


10月25日,周五


  通过和运维部门的沟通(此过程略去N多字)得知,文件的最后修改时间是不可靠的,还是要以MD5和数字签名为准。的确,后来我也从资料得知,文件的最后修改时间是可以通过SetFileTime系统API来修改的。而我们也将修改时间正确的加壳加签名的exe放在了那个网吧里,仍然无法正常启动。因此可以确认之前的文件修改时间是不可靠的。运维并没有给错版本。

  这一天我和运维人员K到网吧去了两趟。K带了很多Sysinternals的工具过去,但全都无法运行。不过这天我们的排查工作还是有一定进展。我们发现,即便我将代码回滚到9月24日同步的版本(即此次更新前的线上版本),重新编译了一个exe,加壳加签名后仍然无法在那个网吧正常启动。因此可以确定此问题和加壳加签名有关。(可见代码版本控制的重要性。)


  同时从运维人员F处得知,9月24日之后,运维使用的加壳软件有过更新。这更加说明加壳软件是值得怀疑的对象。F曾在微软做过技术支持,对此类问题应该更有经验。可惜F正在休假中,只能等下周一。同时F也开始发信给加壳软件厂商进行沟通。


10月28日,周一


  由于我第一次到客服现场抓过的dump均显示程序卡在了WinVerifyTrust的调用上,因此我决定在当前代码中把WinVerifyTrust调用去掉,重新编译了一个exe,看看试验结果如何。

  运维试验后反馈:采用老版的加壳软件加壳我的未去掉WinVerifyTrust的新exe可以正常启动;而采用新版加壳软件加壳我去掉WinVerifyTrust调用的exe,也可以正常启动。这的确可以在一定程度上证明此问题也和数字签名验证有关。


  同一天,F用ProcDump在网吧抓到了dump,用WinDbg分析,发现程序卡住是因为死锁。


  分析过程如下:


  使用!locks命令列出当前被锁住的资源,发现有3个锁。

0:000> !locks

CritSec ntdll!LdrpLoaderLock+0 at 7c99e174
LockCount          3
RecursionCount     2
OwningThread       4e0
EntryCount         7
ContentionCount    7
*** Locked

CritSec crypt32!hCertStoreInst+2c at 76666214
LockCount          1
RecursionCount     1
OwningThread       938
EntryCount         1
ContentionCount    1
*** Locked

CritSec GdiPlus!BackgroundThreadCriticalSection::critSec+0 at 4b0172a4
LockCount          0
RecursionCount     1
OwningThread       4e0
EntryCount         0
ContentionCount    0
*** Locked

Scanned 320 critical sections

  然后看看各个线程里有哪些调用栈在等待这些锁住的Critical Section,并且又是谁占用了这些Critical Section。











             


  WinDbg的帮助里也有一节是专门讲如何分析死锁的。



  因为我的程序是32位的,WinAPI的调用都用了STDCALL,也即栈传参,所以调用栈里的参数是准确可见的。如果是64位的Release版程序,调用约定走R8/R9/RCX/RDX寄存器的传参,就几乎没法看了。


  分析发现,0号线程(主线程)正等待进入一个Critical Section 7c99e174


ChildEBP RetAddr  Args to Child              
0012f7d4 7c92df5a 7c939b23 00000170 00000000 ntdll!KiFastSystemCallRet
0012f7d8 7c939b23 00000170 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
0012f860 7c921046 0199e174 7c93217e 7c99e174 ntdll!RtlpWaitForCriticalSection+0x132
0012f868 7c93217e 7c99e174 c0150008 00000001 ntdll!RtlEnterCriticalSection+0x46
0012f8a4 7c9363fb 00000001 00000000 0012f904 ntdll!LdrLockLoaderLock+0xea
0012fb40 7c801bbd 00142fa0 0012fb8c 0012fb6c ntdll!LdrLoadDll+0xd6
0012fba8 7c801d72 7ffdfc00 00000000 00000000 kernel32!LoadLibraryExW+0x18e
0012fbbc 7c801da8 0014a020 00000000 00000000 kernel32!LoadLibraryExA+0x1f
0012fbd8 77db8810 0014a020 77db791d 7666619c kernel32!LoadLibraryA+0x94
0012fc94 765eaa36 0012fccc 00000000 00000000 advapi32!CryptAcquireContextA+0x512
0012fcc4 76c04130 00000000 0012fe54 76c2a000 crypt32!I_CryptGetDefaultCryptProv+0x99
0012fcdc 76c030a6 0012fd3c 00000000 0012fe24 wintrust!_FillProviderData+0x45
0012fdd8 76c02f4e 00000000 0012fe54 00000000 wintrust!_VerifyTrust+0x24e
0012fdfc 00408ebe 00000000 0012fe54 0012fe24 wintrust!WinVerifyTrust+0x4e


  而该Critical Section,当前被27号线程所占有。


!cx 7c99e174 ntdll!LdrpLoaderLock

dt ntdll!_RTL_CRITICAL_SECTION  0x7c99e174
   +0x000 DebugInfo        : 0x7c99e1a0 _RTL_CRITICAL_SECTION_DEBUG
   +0x004 LockCount        : 3
   +0x008 RecursionCount   : 2
   +0x00c OwningThread     : 0x000004e0
   +0x010 LockSemaphore    : 0x00000170
   +0x014 SpinCount        : 0

dt ntdll!_RTL_CRITICAL_SECTION_DEBUG  0x7c99e1a0
   +0x000 Type             : 0
   +0x002 CreatorBackTraceIndex : 0
   +0x004 CriticalSection  : 0x7c99e174 _RTL_CRITICAL_SECTION
   +0x008 ProcessLocksList : _LIST_ENTRY [ 0x7c99e528 - 0x7c99e508 ]
   +0x010 EntryCount       : 7
   +0x014 ContentionCount  : 7
   +0x018 Spare            : [2] 0

   Critical Section is LOCKED, with 2 Waiters

Owner Thread:
    ~27
kb   !kp 27    !t 27    !t 06c4.04e0  !teb 7ff90000


  查看27号线程的Call Stack,发现它在等待进入另一个Critical Section 76666214。同时我们还发现程序被一个叫HintSock.dll的动态链接库注入了。这是Pubwin网吧计费软件的一个模块。


ChildEBP RetAddr  Args to Child              
036edc18 7c92df5a 7c939b23 000001c8 00000000 ntdll!KiFastSystemCallRet
036edc1c 7c939b23 000001c8 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
036edca4 7c921046 00666214 765eaa15 76666214 ntdll!RtlpWaitForCriticalSection+0x132
036edcac 765eaa15 76666214 00175178 00000001 ntdll!RtlEnterCriticalSection+0x46
036edcc8 765ffb97 00000000 00000000 036edd88 crypt32!I_CryptGetDefaultCryptProv+0x78
036edce4 7660d3fe 00010001 00000000 00000000 crypt32!CryptMsgOpenToDecode+0x55
036edd48 7660541c 00000000 036eded0 00000400 crypt32!I_CryptQueryObject+0x275
036edde0 0373fac4 00000001 036eded0 00000400 crypt32!CryptQueryObject+0xe7
WARNING: Stack unwind information not available. Following frames may be wrong.
036ee0f4 037434f1 036ee990 036ee98c 036ee808 HintSock!SetAlarmURL+0xea24
036eeaac 0377fbba 00171dc0 03820720 00000000 HintSock!SetAlarmURL+0x12451
036eeac8 0382e261 03730000 00000000 00000000 HintSock!GetLogInfo+0x3a6ca
036eeb04 7c92118a 03730000 00000001 00000000 HintSock!PubWinSendData+0xaaf61
036eeb24 7c93b5d2 0382e1f0 03730000 00000001 ntdll!LdrpCallInitRoutine+0x14
036eec2c 7c9362db 00000000 c0150008 00000000 ntdll!LdrpRunInitializeRoutines+0x344
036eeed8 7c93643d 00000000 0014f378 036ef1cc ntdll!LdrpLoadDll+0x3e5
036ef180 7c801bbd 0014f378 036ef1cc 036ef1ac ntdll!LdrLoadDll+0x230
036ef1e8 77d28055 036ef24c 00000000 00000008 kernel32!LoadLibraryExW+0x18e
036ef214 7c92e473 036ef224 00000094 00000094 user32!__ClientLoadLibrary+0x32
036ef2b4 77d194be 77d4215b 001300c2 00000081 ntdll!KiUserCallbackDispatcher+0x13
036ef2e8 100032f7 0001026b 00000000 00000000 user32!NtUserMessageCall+0xc
036ef48c 77d31923 00000000 00000000 036ef4d8 hinthk_10000000+0x32f7
036ef4c0 77d4f460 00040000 00000000 036ef4d8 user32!DispatchHookA+0x101
036ef4e8 77d2ce7c 00c029a0 00000081 00000000 user32!fnHkINLPCWPSTRUCTA+0x4f
036ef518 7c92e473 036ef528 00000060 00000060 user32!__fnINLPCREATESTRUCT+0x8b
036ef584 77d2e389 77d2e34f 80000000 0000c0f0 ntdll!KiUserCallbackDispatcher+0x13
036efa28 77d2e442 80000000 0000c0f0 036efac0 user32!NtUserCreateWindowEx+0xc
036efad4 77d2e4dc 80000000 0000c0f0 036efac0 user32!_CreateWindowEx+0x1ed
036efb10 4aeaa30b 00000000 0000c0f0 4aeaa3f0 user32!CreateWindowExA+0x33
036eff7c 4aea747e 7c80a174 00000011 00000000 GdiPlus!InternalNotificationStartup+0x91
036effb4 7c80b729 00000000 7c80a174 00000011 GdiPlus!BackgroundThreadProc+0x28
036effec 00000000 4aea7456 00000000 00000000 kernel32!BaseThreadStart+0x37


  而该Critical Section,当前被0号线程所占有。


!cx 76666214 crypt32!hCertStoreInst+0x2c

dt ntdll!_RTL_CRITICAL_SECTION  0x76666214
   +0x000 DebugInfo        : 0x0014aa70 _RTL_CRITICAL_SECTION_DEBUG
   +0x004 LockCount        : 1
   +0x008 RecursionCount   : 1
   +0x00c OwningThread     : 0x00000938
   +0x010 LockSemaphore    : 0x000001c8
   +0x014 SpinCount        : 0

dt ntdll!_RTL_CRITICAL_SECTION_DEBUG  0x0014aa70
   +0x000 Type             : 0
   +0x002 CreatorBackTraceIndex : 0
   +0x004 CriticalSection  : 0x76666214 _RTL_CRITICAL_SECTION
   +0x008 ProcessLocksList : _LIST_ENTRY [ 0x14aaa0 - 0x14a6a0 ]
   +0x010 EntryCount       : 1
   +0x014 ContentionCount  : 1
   +0x018 Spare            : [2] 0

   Critical Section is LOCKED, with 1 Waiters

Owner Thread:
     ~0
kb   !kp 0     !t 0     !t 06c4.0938  !teb 7ffdf000


  因此0号线程和27号线程形成了一个死锁!


  于是回到我的代码中。其实我的代码从main函数入口到调用WinVerifyTrust之间,并没有开启任何其它线程,并且只做了两件事:一是调用GdiplusStartup初始化GDI+,二就是调用WinVerifyTrust,真的没做任何其它事情。结合F对dump的分析结果,可以看出GdiplusStartup内部开启了多线程来执行初始化工作,如dump中的27号线程。那么死锁的原因,根据F的推测,即是新版与老版加壳软件以及机器上某些第三方dll引起的某个线程执行速度或时序上的差异,造成被dll注入的GDI+初始化线程执行速度变慢,使其有了和主线程死锁的机会。难怪加壳软件厂商那边至今还是一头雾水。


  分析出这个原因后,我这边代码上也有了解决方案:调换GdiplusStartup和WinVerifyTrust的调用次序,先调用WinVerifyTrust,待数字签名验证全部完成后,再调用GdiplusStartup,执行GDI+。这样就没有死锁的机会了。


10月29日,周二


  经运维试验,采用新版加壳软件,对我给出的先调用WinVerifyTrust再调用GdiplusStartup的exe进行加壳加签名,处理后的exe可以那个网吧正常启动。至此,程序卡住的问题被完美解决。


  PS:后来我按照F的分析方法分析了我一开始从客服现场抓的dump,发现程序还没走到RtlpWaitForCriticalSection这一步。看来我们当时抓dump抓早了啊。

阅读更多
版权声明:本文为博主原创文章,未经博主允许不得转载。 https://blog.csdn.net/zzxiang1985/article/details/13767037
想对作者说点什么? 我来说一句

C++死锁的检测与解除

2011年12月01日 4KB 下载

没有更多推荐了,返回首页

加入CSDN,享受更精准的内容推荐,与500万程序员共同成长!
关闭
关闭