我一直在用Windows Live Toolbar中的Live Favorites来同步我的书签信息，但是速度总是很慢，甚至完全死掉。今天闲来无事，刚看到Mark的一篇Blog http://blogs.technet.com/markrussinovich/archive/2006/08/31/453100.aspx，对于他不放过任何问题的精神很是钦佩，准备效法一番。正好遇到IE关闭之后停在那边一直不动，怎么点也没有反应，便准备动手调试一下看看问题出在哪里。
启动WinDbg，Attach到IExplore.exe进程上，我依次检查每个Thread的调用栈，发现3号线程的情况最为诡异，其Call Stack如下：
| 0:003> kb ChildEBP RetAddr Args to Child 01d5f4f4 77a806a0 77a5b18c 000006a8 00000000 ntdll!KiFastSystemCallRet 01d5f4f8 77a5b18c 000006a8 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc [f:\vistartm.obj.x86fre\base\ntdll\daytona\objfre\i386\usrstubs.asm @ 2971] 01d5f55c 77a5b071 00000000 00000000 00000000 ntdll!RtlpWaitOnCriticalSection+0x154 01d5f584 031e5480 040851c4 01d5f5bc 031e55eb ntdll!RtlEnterCriticalSection+0x152 WARNING: Stack unwind information not available. Following frames may be wrong. 01d5f59c 031f08f9 040851c4 00000001 0870611e WLFExt+0x15480 01d5f5d4 031ea967 08706136 03c96650 040851c0 WLFExt+0x208f9 01d5f5fc 031ea9b7 040818f0 01d5f62c 031e9fba WLFExt+0x1a967 01d5f608 031e9fba 00000001 031ec103 031df277 WLFExt+0x1a9b7 01d5f62c 64853ac8 040818f0 00000000 03c968b8 WLFExt+0x19fba 01d5f658 64856164 00000001 80004005 03c96650 msntb!DllUnregisterServer+0xb9a0 01d5f700 7092e468 03c96650 004f4b64 03d44938 msntb!DllUnregisterServer+0xe03c 01d5f720 7093edb2 03c96650 00000000 004ec83c ieframe!Ordinal160+0xb569 01d5f748 70907931 00000001 004ec778 7092e5cc ieframe!Ordinal222+0xd2b1 01d5f77c 7092fc12 004ec850 00000000 00000002 ieframe!Ordinal300+0xc96f 01d5f798 7091dc4a 004eb08c 01d5f7b4 7091dc69 ieframe!SetQueryNetSessionCount+0x1328 01d5f7a4 7091dc69 004e5c4c 00000002 01d5f7cc ieframe!Ordinal224+0xd15a 01d5f7b4 7092fb81 004e5c4c 00000002 00000000 ieframe!Ordinal224+0xd179 01d5f7cc 7090c15c 004eb08c 00060838 00000002 ieframe!SetQueryNetSessionCount+0x1297 01d5f7e8 7090ba6d 004e5c4c 00060838 00000002 ieframe!Ordinal101+0x1ad2 01d5f850 7091ac8a 004e5c4c 00060838 00000002 ieframe!Ordinal101+0x13e3 |
可以看到这个线程正在准备Enter一个Critical Section，但是由于该Critical Section已经被别人占用，并且Spin时间过长，已经调用ntdll!ZwWaitForSingleObject进入了内核模式开始等待了。虽说Critical Section并非内核对象，但是Critical Section仍然可以导致线程进入等待状态。假想一下如果一个线程一直在Spin，反复循环等待Critical Section被别人释放，那么这种方式该有多占CPU。因此Windows会让线程Spin一段时间之后继续等待。
那么这个线程到底在做什么事情呢？可以看到有两个module非常可疑：wlfext和msntb。
先用lm命令查看一下wlfext是什么：
| 0:003> lmvm wlfext start end module name 031d0000 03225000 WLFExt (export symbols) WLFExt.dll Loaded symbol image file: WLFExt.dll Image path: C:\Program Files\Windows Live Favorites\WLFExt.dll Image name: WLFExt.dll Timestamp: Tue Feb 13 07:52:08 2007 (45D0FDA8) CheckSum: 00059C4B ImageSize: 00055000 File version: 3.1.0.130 Product version: 3.1.0.130 File flags: 0 (Mask 3F) File OS: 4 Unknown Win32 File type: 1.0 App File date: 00000000.00000000 Translations: 0409.04b0 CompanyName: Microsoft Corporation ProductName: Windows Live Favorites for Windows Live Toolbar InternalName: WLFExt OriginalFilename: WLFExt.dll ProductVersion: 03.01.0000.0130 FileVersion: 03.01.0000.0130 FileDescription: Windows Live Favorites for Windows Live Toolbar LegalCopyright: Copyright© Microsoft Corporation 2005-2006. All rights reserved. |
很清楚了，这是Windows Live Favorites！
再看看msntb：
| 0:003> lmvm msntb start end module name 64830000 648b7000 msntb (export symbols) msntb.dll Loaded symbol image file: msntb.dll Image path: C:\Program Files\Windows Live Toolbar\msntb.dll Image name: msntb.dll Timestamp: Tue Feb 13 07:55:00 2007 (45D0FE54) CheckSum: 0008650F ImageSize: 00087000 File version: 3.1.0.130 Product version: 3.1.0.130 File flags: 0 (Mask 3F) File OS: 4 Unknown Win32 File type: 2.0 Dll File date: 00000000.00000000 Translations: 0409.04b0 CompanyName: Microsoft Corporation ProductName: Windows Live Toolbar InternalName: msntb.dll OriginalFilename: msntb.dll ProductVersion: 03.01.0000.0130 FileVersion: 03.01.0000.0130 FileDescription: Windows Live Toolbar for Internet Explorer LegalCopyright: © Microsoft Corporation. All rights reserved. |
毫不意外，这是Windows Live Toolbar。
根据Call Stack来看，Windows Live Toolbar正在尝试Unregister自身（DllUnregisterServer），但是这个正确吗？由于LM命令的显示我们可以看到对于MSNTB.dll我们并没有PDB，而是只有Dll本身的输出的符号表:
| 0:003> lmvm msntb start end module name 64830000 648b7000 msntb (export symbols) msntb.dll Loaded symbol image file: msntb.dll Image path: C:\Program Files\Windows Live Toolbar\msntb.dll |
而光看这个是根本不准确的，所以这个Callstack显示的01d5f658 64856164 00000001 80004005 03c96650 msntb!DllUnregisterServer+0xb9a0这一项不能相信，同时也可以通过0xb9a0这个巨大的偏移量也可以看出确实不正确（哪有一个函数会有那么长，有超过0xb9a0）。虽然其他的地方可以下到PDB，但是我其实不太关心到底在做什么，没有源代码能做的事情也很有限。
再回到之前的Crtical Section。我们可以看一下，这个Critical Section到底是怎么回事。可以使用!locks命令显示进程中所有的锁的状态：
| 0:003> !locks CritSec +40851c4 at 040851c4 WaiterWoken No LockCount 1 RecursionCount 1 OwningThread 3a0 EntryCount 0 ContentionCount 1 *** Locked Scanned 1413 critical sections |
比较运气好，这里只有一个Critical Section 040851c4被Lock住。为了确认这个Critcal Section到底是不是3号Thread正在等待的，我们可以看看CallStack中的信息：
| ChildEBP RetAddr Args to Child 01d5f584 031e5480 040851c4 01d5f5bc 031e55eb ntdll!RtlEnterCriticalSection+0x152 01d5f850 |
这里可以看到，第一个Arg正好就是040851c4，也就是被Lock住的那一个。
回头再看一下!locks的输出，可以看到是Thread 0x3a0在Own这个Critical Section，但是检查一下，发现根本就没有这个Thread。
到此事实就比较清楚了，在Windows Live Favorites中有一个Bug导致在退出的时候，WLFEXT.dll中的某个函数在线程A中等待某个Critical Section，而这个Crtical Section已经被某个线程B所Own，并且这个线程B已经由于某种原因已经被Terminate（可能性比较大的是出错退出），因此线程A死锁，导致整个IE死锁。我顺便用.dump指令收集了一个Mini Dump，准备星期一给Windows Live那边Log一个Bug，毕竟修好问题才是最重要的。
Trackback: http://tb.blog.csdn.net/TrackBack.aspx?PostId=1737651
