|
这是我自己机器上遇到的一个问题.
问题描述:
Windows Xp在启动过程中,进入Welcome screen之前,一切正常.
Welcome screen出来后,一般来说,第一步操作当然是移动鼠标到用户的图标上,然后点击,进行登录. 现在移动鼠标正常,但是,当鼠标移动到用户的图标上面去的时候,正常情况下,图标应该会由暗变亮,但是,现在鼠标在上面的时候,没有任何反应.
此时再继续移动鼠标和击键,桌面仍然没有反应,持续鼠标键若干次(总共约是6次),最后一次,出beep音后,鼠标指针也hang住,没有反应.至此系统就完全hang了.
以上情况只是偶尔出现,不是一个必然现象.
分析:
由于user input到最后都被hang住了, local debug就不方便了. 先考虑用键盘手动制造一个bugcheck,当然,这要正常登录进系统,改了注册表,下次再hang的时候就可以capture一个full memory dump. 这只要加入一个DWORD注册表值HKLM\System\CurrentControlSet\Services\i8042prt\Parameters\CrashOnCtrlScroll，并将其设置为1,下次hang的时候,按下Ctrl,同时候再按两个ScrollLock,就可以得到dump了.
得到full memory dump, 第一步使用!analyze,但并没有得到很有用的信息, 仅提示MANUALLY_INITIATED_CRASH.
由于登录UI是由winlogon.exe维护的,接下来是看Winlogon.exe进程的message loop, 从这里看,似乎在正常的,它正在等待input message.到这里似乎一下子无从下手了.
接下来考虑,从键盘输入然后到Winlogon.exe接收到WM_KEYDOWN之类的消息这个过程,中间有哪些地方可能被卡住了.
能手动制造crash,说明ISR还是能响应的. 鼠标消息基本上是从ISR到DPC到Desktop Thread再到RIT(Raw Input Thread)最后发到线程message queue,下面先检查Desktop Thread和RIT.
// stack of Raw Input Thread
THREAD 82e5c560 Cid 02b4.02d8 Teb: 7ffd8000 Win32Thread: e1a20710 WAIT: (Executive) KernelMode Non-Alertable
82e6cfc0 SynchronizationEvent
82e5c650 NotificationTimer
IRP List:
83192bb0: (0006,0190) Flags: 00000970 Mdl: 00000000
Not impersonating
DeviceMap e1005450
Owning Process 82eb3020 Image: csrss.exe
Attached Process N/A Image: N/A
Wait Start TickCount 4307 Ticks: 229 (0:00:00:03.578)
Context Switch Count 848 LargeStack
UserTime 00:00:00.000
KernelTime 00:00:00.000
Start Address winsrv!StartCreateSystemThreads (0x764e7cdf)
Stack Init f828f000 Current f828e9e8 Base f828f000 Limit f828c000 Call 0
Priority 15 BasePriority 13 PriorityDecrement 0 DecrementCount 0
ChildEBP RetAddr
f828ea00 804dd0f7 nt!KiSwapContext+0x2e
f828ea0c 804dd143 nt!KiSwapThread+0x46
f828ea34 80517972 nt!KeWaitForSingleObject+0x1c2
f828ea70 804e589e nt!ExpWaitForResource+0xd2
f828ea80 bf800aee nt!ExAcquireResourceExclusiveLite+0x6f
f828ea8c bf87b1d7 win32k!EnterCrit+0x14
f828ead4 bf895584 win32k!ProcessQueuedMouseEvents+0x23
f828ed30 bf879fa3 win32k!RawInputThread+0x5b9
f828ed40 bf80108a win32k!xxxCreateSystemThreads+0x60
f828ed54 804df7ec win32k!NtUserCallOneParam+0x23
f828ed54 7c92eb94 nt!KiFastCallEntry+0xf8
0075ffe0 764eba1a ntdll!KiFastSystemCallRet
// stack of Desktop Thread.
THREAD 82e6c940 Cid 02b4.02dc Teb: 7ffd7000 Win32Thread: e1a00870 WAIT: (Executive) KernelMode Non-Alertable
82e6cfc0 SynchronizationEvent
82e6ca30 NotificationTimer
IRP List:
83186728: (0006,0190) Flags: 00000970 Mdl: 00000000
82e51278: (0006,0190) Flags: 00000970 Mdl: 00000000
Not impersonating
DeviceMap e1005450
Owning Process 82eb3020 Image: csrss.exe
Attached Process N/A Image: N/A
Wait Start TickCount 4373 Ticks: 163 (0:00:00:02.546)
Context Switch Count 799 LargeStack
UserTime 00:00:00.000
KernelTime 00:00:00.015
Start Address winsrv!StartCreateSystemThreads (0x764e7cdf)
Stack Init f829f000 Current f829e834 Base f829f000 Limit f829c000 Call 0
Priority 15 BasePriority 13 PriorityDecrement 0 DecrementCount 16
ChildEBP RetAddr
f829e84c 804dd0f7 nt!KiSwapContext+0x2e
f829e858 804dd143 nt!KiSwapThread+0x46
f829e880 80517972 nt!KeWaitForSingleObject+0x1c2
f829e8bc 804e589e nt!ExpWaitForResource+0xd2
f829e8cc bf800aee nt!ExAcquireResourceExclusiveLite+0x6f
f829e8d8 bf90fa59 win32k!EnterCrit+0x14
f829e928 bf87b52a win32k!UserBeep+0xd4
f829e938 bf87bfd7 win32k!QueueMouseEvent+0x54
f829e97c bf87aef9 win32k!ProcessMouseInput+0x1b1
f829e98c 804f0b50 win32k!InputApc+0x4e
f829e9d4 804efed9 nt!KiDeliverApc+0x124
f829e9ec 804e4b7d nt!KiSwapThread+0x64
f829ea24 bf807c60 nt!KeWaitForMultipleObjects+0x284
f829ea5c bf890fec win32k!xxxMsgWaitForMultipleObjects+0xb0
f829ed30 bf87a011 win32k!xxxDesktopThread+0x333
f829ed40 bf80108a win32k!xxxCreateSystemThreads+0x6a
f829ed54 804df7ec win32k!NtUserCallOneParam+0x23
f829ed54 7c92eb94 nt!KiFastCallEntry+0xf8
0079ffe0 764eba1a ntdll!KiFastSystemCallRet
从上面stack可以看到,DeskTop thread和RIT都在wait,并且都在等待win32k!EnterCrit这个critical section. 由于这时候没有什么I/O(从指示灯看的),
从这里可以猜测系统里面发生了deadlock.下面再确认是不是这样,
kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks....
Resource @ nt!CmpRegistryLock (0x80558360) Exclusively owned
Contention Count = 41
NumberOfSharedWaiters = 6
Threads: 82e1cb28-01<*> 837b6020-01 82e06ae0-01 82e7c020-01
837b87a8-01 82dd84f0-01 82eb2020-01
KD: Scanning for held locks.
Resource @ 0x837b27a0 Exclusively owned
Contention Count = 2
NumberOfExclusiveWaiters = 1
Threads: 837b6020-01<*>
Threads Waiting On Exclusive Access:
82e1cb28
KD: Scanning for held locks...............
Resource @ 0x82eb27a0 Exclusively owned
Contention Count = 174
NumberOfExclusiveWaiters = 2
Threads: 82eb2020-01<*>
Threads Waiting On Exclusive Access:
82e5c560 82e6c940
KD: Scanning for held locks........................
Resource @ 0x82dff808 Shared 1 owning threads
Threads: 837b8c9b-01<*> *** Actual Thread 837b8c98
KD: Scanning for held locks....
Resource @ 0x82ec4a50 Shared 1 owning threads
Threads: 837b8c9b-01<*> *** Actual Thread 837b8c98
KD: Scanning for held locks.
Resource @ 0x831e0b88 Shared 1 owning threads
Threads: 831864cb-01<*> *** Actual Thread 831864c8
1440 total locks, 6 locks currently held
从上面的输出很容易找到,thread(82e1cb28)(后面简称thread1)和thread(837b6020)(后面简称thread2)确实发生了deadlock,两个线程都以exclusive的方式分别持有nt!CmpRegistryLock (0x80558360) (后称lock1)和0x837b27a0(后称lock2), 同时,thread1请求lock2的exclusive access,thread2请求lock1的share access.
下面再看这两个线程的stack,
//thread1
kd> !thread 82e1cb28
THREAD 82e1cb28 Cid 03a4.03a8 Teb: 7ffdf000 Win32Thread: e1b90540 WAIT: (Executive) KernelMode Non-Alertable
82df2f00 SynchronizationEvent
82e1cc18 NotificationTimer
Not impersonating
DeviceMap e1005450
Owning Process 82e1cda0 Image: logonui.exe
Attached Process N/A Image: N/A
Wait Start TickCount 4471 Ticks: 65 (0:00:00:01.015)
Context Switch Count 1399 LargeStack
UserTime 00:00:00.031
KernelTime 00:00:01.296
Win32 Start Address logonui!WinMainCRTStartup (0x0100b95d)
Start Address kernel32!BaseProcessStartThunk (0x7c810665)
Stack Init f77a7000 Current f77a691c Base f77a7000 Limit f77a2000 Call 0
Priority 14 BasePriority 8 PriorityDecrement 6 DecrementCount 16
ChildEBP RetAddr Args to Child
f77a6934 804dd0f7 82e1cb98 82e1cb28 804dd143 nt!KiSwapContext+0x2e
f77a6940 804dd143 00000000 837b27a0 82e1cb28 nt!KiSwapThread+0x46
f77a6968 80517972 00000000 00000000 00000000 nt!KeWaitForSingleObject+0x1c2
f77a69a4 804e589e e1c002a0 e1c002b8 f77a6a58 nt!ExpWaitForResource+0xd2
f77a69b4 8056510e 837b27a0 00000001 82de9390 nt!ExAcquireResourceExclusiveLite+0x6f
f77a6a58 805652ad 00000000 82e1cda0 e1c002b8 nt!ObpIncrementHandleCount+0x5b
f77a6ac0 80568527 00000000 e1c002b8 837b2680 nt!ObpCreateHandle+0x17d
f77a6b10 80568dfd 00000000 837b2680 ffffff00 nt!ObOpenObjectByName+0x28c
f77a6be4 804df7ec f77a6ca4 0002001f f77a6c7c nt!NtOpenKey+0x1af
f77a6be4 804de019 f77a6ca4 0002001f f77a6c7c nt!KiFastCallEntry+0xf8
f77a6c68 806573f2 f77a6ca4 0002001f f77a6c7c nt!ZwOpenKey+0x11
f77a6ca8 80653b84 e1d80b60 00000020 e1c5ffb8 nt!CmpRemoveFromHiveFileList+0x48
f77a6cc0 8064d4a3 e1d80b60 00000020 e1664bd8 nt!CmUnloadKey+0x55
f77a6d58 804df7ec 0007ebc0 0007ebd8 7c92eb94 nt!NtUnloadKey+0x18c
f77a6d58 7c92eb94 0007ebc0 0007ebd8 7c92eb94 nt!KiFastCallEntry+0xf8
0007ebb0 7c92e918 77e0bbc0 0007ebc0 00000018 ntdll!KiFastSystemCallRet
0007ebb4 77e0bbc0 0007ebc0 00000018 00000250 ntdll!NtUnloadKey+0xc
0007ebd8 77e0527a 00000250 0007ebf0 0007ec48 ADVAPI32!LocalBaseRegUnLoadKey+0x51
0007ebfc 73ce9a58 80000003 000a4b68 00000003 ADVAPI32!RegUnLoadKeyW+0x68
0007ec28 73ce5fd9 000000d8 00000009 000a07d8 shgina!CUserProfile::~CUserProfile+0x39
0007ec88 73ce6ac9 0007ecd8 77d19e36 0067f770 shgina!CLogonUser::_GetUnreadMail+0xfc
0007eca4 73ce6af8 01001d8c 0007ecd8 00000000 shgina!CLogonUser::_UserSettingAccessor+0x226
0007ecb8 0100a492 000c7834 01001d8c 0007ecd8 shgina!CLogonUser::get_setting+0x18
0007fd10 0100ac72 00000001 000003f6 00000001 logonui!LogonAccount::UpdateNotifications+0x209
0007fd2c 0100784a 00000001 0007fdcc 01007538 logonui!LogonFrame::UpdateUserStatus+0x65
0007fd64 77d18734 00010038 00000113 000003f6 logonui!LogonWindowProc+0x312
0007fd90 77d18816 01007538 00010038 00000113 USER32!InternalCallWinProc+0x28
0007fdf8 77d189cd 00000000 01007538 00010038 USER32!UserCallWinProcCheckWow+0x150
0007fe58 77d18a10 0007fe7c 00000000 0007fe98 USER32!DispatchMessageWorker+0x306
0007fe68 01017799 0007fe7c 77d1d8a4 00000000 USER32!DispatchMessageW+0xf
0007fe98 0100b672 7c80b6a1 000a231c 00000000 logonui!DirectUI::StartMessagePump+0x48
0007ff1c 0100bad1 01000000 00000000 00653ac0 logonui!WinMain+0x32d
0007ffc0 7c816fd7 00166860 0006e9fc 7ffd8000 logonui!WinMainCRTStartup+0x174
0007fff0 00000000 0100b95d 00000000 78746341 kernel32!BaseProcessStart+0x23
//thread2
kd> !thread 837b6020
THREAD 837b6020 Cid 0004.003c Teb: 00000000 Win32Thread: 00000000 WAIT: (Executive) KernelMode Non-Alertable
82e7b988 Semaphore Limit 0x7fffffff
837b6110 NotificationTimer
Not impersonating
DeviceMap e1005450
Owning Process 837b9660 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 4469 Ticks: 67 (0:00:00:01.046)
Context Switch Count 750
UserTime 00:00:00.000
KernelTime 00:00:00.062
Start Address nt!ExpWorkerThread (0x804e5196)
Stack Init f84d3000 Current f84d244c Base f84d3000 Limit f84d0000 Call 0
Priority 14 BasePriority 12 PriorityDecrement 2 DecrementCount 16
*** ERROR: Module load completed but symbols could not be loaded for sptd.sys
ChildEBP RetAddr Args to Child
f84d2464 804dd0f7 837b6090 837b6020 804dd143 nt!KiSwapContext+0x2e
f84d2470 804dd143 00000000 80558360 837b6020 nt!KiSwapThread+0x46
f84d2498 80517972 00000000 00000000 00000000 nt!KeWaitForSingleObject+0x1c2
f84d24d4 804fb40f f84d2590 837b2680 f84d2584 nt!ExpWaitForResource+0xd2
f84d24e8 80567012 80558360 00000001 8056c74c nt!ExAcquireResourceSharedLite+0xb2
f84d24f4 8056c74c f84d2590 837b2680 f84d2584 nt!CmpLockRegistry+0x27
f84d252c 8056c8a1 e164e250 00000001 f84d2560 nt!CmpSecurityMethod+0x1e
f84d2568 80566006 e164e250 f84d2590 e164e24c nt!ObGetObjectSecurity+0x96
f84d2594 80565166 e164e250 f84d26e8 00000001 nt!ObCheckObjectAccess+0x29
f84d2644 805652ad 00000001 837b9660 e164e250 nt!ObpIncrementHandleCount+0x1f7
f84d26ac 8056cc49 00000001 e164e250 00000000 nt!ObpCreateHandle+0x17d
f84d277c f7f7f309 e164e250 00000040 00000000 nt!ObOpenObjectByPointer+0xa4
WARNING: Stack unwind information not available. Following frames may be wrong.
f84d2848 80567b09 e101df24 00000300 e101df28 sptd+0x8309
f84d28e4 f7f9165c f84d290c f84d2914 00000000 nt!ObpDecrementHandleCount+0x121
f84d2958 8054bb38 0000005c f7fd59e0 00000001 sptd+0x1a65c
f84d29bc f7f98cb2 ed952000 00068000 f84d2a7c nt!ExFreePoolWithTag+0x676
f84d2aa8 8062d1c9 f84d2cf0 00000000 f84d2b44 sptd+0x21cb2
f84d2ac8 805f16ce f84d2cf0 00000000 f84d2b44 nt!PsCallImageNotifyRoutines+0x36
f84d2c6c 805a4d14 f84d2cf0 00000000 00000000 nt!MmLoadSystemImage+0x999
f84d2d4c 805a51fc 00000308 00000001 00000000 nt!IopLoadDriver+0x370
f84d2d74 804e526b 00000308 00000000 837b6020 nt!IopLoadUnloadDriver+0x45
f84d2dac 8057e0f1 f7816cf4 00000000 00000000 nt!ExpWorkerThread+0x100
f84d2ddc 804f927a 804e5196 00000001 00000000 nt!PspSystemThreadStartup+0x34
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16
kd> dS f84d2cf0
e1c04290 "\??\C:\WINDOWS\system32\Drivers\"
e1c042d0 "vmx86.sys"
可thread1是logonui.exe的主线程,正在执行ntdll!NtUnloadKey,thread2是一个System thread,正在load driver,从其参数可以找到,正在load的driver就是vmx86.sys,在load的过程中会调用registered image notify functions,应该是sptd.sys注册了这个function,所以进入了sptd.sys执行. 在sptd.sys里会调用nt!ObOpenObjectByPointer,这个方法再去调用nt!CmpLockRegistry对registry进行lock,但是这个lock已经被thread1以exclusive的方式占用了, 而thread1也在等待thread2以exclusive方式持有的与Object相关的lock, 这里就发生了deadlock.
下面如果再要继续找原因,可以参考WRK的code,几个lock都发生在了nt!ObpIncrementHandleCount里面.
到这里解决方法也就比较明显了,问题是由sptd.sys导致的,可以search到sptd.sys是一个光驱软件的驱动,我机器上装了alcohol 120%,卸载它,应该可以解决这个问题,另外还可以尝试升级这个软件.
文中肯定有不足或者不对的分析,欢迎补充,指正.
|