Shutdown delay

Hello,

I am troubleshooting a ~5 minute delay that occurs during shutdown of Windows XP SP3. The failure is such that after the “Windows is shutting down…” dialog box goes away, there remains only a solid color background and the mouse cursor, which can move. I have the system connected to a live debugger. I have been reading a lot of posts and trying a lot of things, but not been able to identify what is causing the delay.

My current best investigative track is from the output of !locks. This shows only one currently held lock, and looking at the thread which holds the lock it is waiting on an Unknown object. This value was passed in as an argument to KiSwapThread, but it seems to be invalid memory. If I let the target system run again for another minute before breaking in again, !locks shows the same information, but the resource memory location is different. I noticed that this thread is part of the System process, and the TEB is null. Further, the WinDbg help for !locks shows a similar Unknown object. Because of this, I am not sure if what I have below is indicating a problem in any way.

0: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks…

Resource @ 0x860b04f8 Shared 1 owning threads
Threads: 89d52b33-01<*> *** Actual Thread 89d52b30
3167 total locks, 1 locks currently held

0: kd> !thread 89d52b30
THREAD 89d52b30 Cid 0004.0020 Teb: 00000000 Win32Thread: 00000000 WAIT: (WrQueue) UserMode Non-Alertable
80564820 Unknown
Not impersonating
DeviceMap e1002150
Owning Process 0 Image:
Attached Process 89d545f0 Image: System
Wait Start TickCount 27516 Ticks: 7 (0:00:00:00.109)
Context Switch Count 10792 NoStackSwap
UserTime 00:00:00.000
KernelTime 00:00:00.968
Start Address nt!ExpWorkerThread (0x8053869e)
Stack Init ba508000 Current ba507d24 Base ba508000 Limit ba505000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0 DecrementCount 16
ChildEBP RetAddr Args to Child
ba507d3c 80503850 89d52ba0 89d52b30 804fcc96 nt!KiSwapContext+0x2f (FPO: [Uses EBP] [0,0,4])
ba507d48 804fcc96 89d79078 80564820 89d52b30 nt!KiSwapThread+0x8a (FPO: [0,0,0])
ba507d74 8053876a 00000000 4e166f01 00000000 nt!KeRemoveQueue+0x22a (FPO: [Non-Fpo])
ba507dac 805cff92 89d79078 00000000 00000000 nt!ExpWorkerThread+0xcc (FPO: [Non-Fpo])
ba507ddc 8054611e 8053869e 00000000 00000000 nt!PspSystemThreadStartup+0x34 (FPO: [Non-Fpo])
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

0: kd> !object 80564820
Object: 80564820 Type: (00000007)
ObjectHeader: 80564808 (old version)
HandleCount: 2312442960 PointerCount: 2312442960
Directory Object: 00000000 Name: ( Name not accessible )

0: kd> dt 80564808 _OBJECT_HEADER
nt!_OBJECT_HEADER
+0x000 PointerCount : 0n-1982524336
+0x004 HandleCount : 0n-1982524336
+0x004 NextToFree : 0x89d51450 Void
+0x008 Type : 0x00000007 _OBJECT_TYPE
+0x00c NameInfoOffset : 0x5 ‘’
+0x00d HandleInfoOffset : 0 ‘’
+0x00e QuotaInfoOffset : 0 ‘’
+0x00f Flags : 0 ‘’
+0x010 ObjectCreateInfo : (null)
+0x010 QuotaBlockCharged : (null)
+0x014 SecurityDescriptor : (null)
+0x018 Body : _QUAD

Thanks in advance,
-John.

That’s a red herring, sometimes the worker threads acquire locks that they
don’t drop and that’s OK (I know this because I tracked this behavior down
to death thinking that it was our bug).

There has to be some other thread out there doing something interesting.
!stacks 2 might shed some light on the interesting threads, or you can try
!uniqstack from the latest issue of The NT Insider:

http://www.osronline.com/OsrDown.cfm/apexts.zip?name=apexts.zip&id=559

That will limit the output to only those threads with unique call chains.

-scott


Scott Noone
Consulting Associate
OSR Open Systems Resources, Inc.
http://www.osronline.com

wrote in message news:xxxxx@windbg…
> Hello,
>
> I am troubleshooting a ~5 minute delay that occurs during shutdown of
> Windows XP SP3. The failure is such that after the “Windows is shutting
> down…” dialog box goes away, there remains only a solid color background
> and the mouse cursor, which can move. I have the system connected to a
> live debugger. I have been reading a lot of posts and trying a lot of
> things, but not been able to identify what is causing the delay.
>
> My current best investigative track is from the output of !locks. This
> shows only one currently held lock, and looking at the thread which holds
> the lock it is waiting on an Unknown object. This value was passed in as
> an argument to KiSwapThread, but it seems to be invalid memory. If I let
> the target system run again for another minute before breaking in again,
> !locks shows the same information, but the resource memory location is
> different. I noticed that this thread is part of the System process, and
> the TEB is null. Further, the WinDbg help for !locks shows a similar
> Unknown object. Because of this, I am not sure if what I have below is
> indicating a problem in any way.
>
>
>
> 0: kd> !locks
> DUMP OF ALL RESOURCE OBJECTS
> KD: Scanning for held
> locks…
>
> Resource @ 0x860b04f8 Shared 1 owning threads
> Threads: 89d52b33-01<*> Actual Thread 89d52b30
> 3167 total locks, 1 locks currently held
>
> 0: kd> !thread 89d52b30
> THREAD 89d52b30 Cid 0004.0020 Teb: 00000000 Win32Thread: 00000000 WAIT:
> (WrQueue) UserMode Non-Alertable
> 80564820 Unknown
> Not impersonating
> DeviceMap e1002150
> Owning Process 0 Image:
> Attached Process 89d545f0 Image: System
> Wait Start TickCount 27516 Ticks: 7 (0:00:00:00.109)
> Context Switch Count 10792 NoStackSwap
> UserTime 00:00:00.000
> KernelTime 00:00:00.968
> Start Address nt!ExpWorkerThread (0x8053869e)
> Stack Init ba508000 Current ba507d24 Base ba508000 Limit ba505000 Call 0
> Priority 13 BasePriority 13 PriorityDecrement 0 DecrementCount 16
> ChildEBP RetAddr Args to Child
> ba507d3c 80503850 89d52ba0 89d52b30 804fcc96 nt!KiSwapContext+0x2f (FPO:
> [Uses EBP] [0,0,4])
> ba507d48 804fcc96 89d79078 80564820 89d52b30 nt!KiSwapThread+0x8a (FPO:
> [0,0,0])
> ba507d74 8053876a 00000000 4e166f01 00000000 nt!KeRemoveQueue+0x22a (FPO:
> [Non-Fpo])
> ba507dac 805cff92 89d79078 00000000 00000000 nt!ExpWorkerThread+0xcc (FPO:
> [Non-Fpo])
> ba507ddc 8054611e 8053869e 00000000 00000000
> nt!PspSystemThreadStartup+0x34 (FPO: [Non-Fpo])
> 00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16
>
> 0: kd> !object 80564820
> Object: 80564820 Type: (00000007)
> ObjectHeader: 80564808 (old version)
> HandleCount: 2312442960 PointerCount: 2312442960
> Directory Object: 00000000 Name: (
Name not accessible ***)
>
> 0: kd> dt 80564808 _OBJECT_HEADER
> nt!_OBJECT_HEADER
> +0x000 PointerCount : 0n-1982524336
> +0x004 HandleCount : 0n-1982524336
> +0x004 NextToFree : 0x89d51450 Void
> +0x008 Type : 0x00000007 _OBJECT_TYPE
> +0x00c NameInfoOffset : 0x5 ‘’
> +0x00d HandleInfoOffset : 0 ‘’
> +0x00e QuotaInfoOffset : 0 ‘’
> +0x00f Flags : 0 ‘’
> +0x010 ObjectCreateInfo : (null)
> +0x010 QuotaBlockCharged : (null)
> +0x014 SecurityDescriptor : (null)
> +0x018 Body : _QUAD
>
>
> Thanks in advance,
> -John.
>
>
>

When in the failed state, I ran !apexts.uniqstack and got 369 threads in the system but only 67 unique. Then I poked around for a bit, including setting .process and .thread. After this, I ran !apexts.uniqstack again and got 369 threads but 131 unique. Is this expected?

I do have a bit of a lead from trying to do some gross poking from the image side. If I call a process called Device Lock before trying to shut down, then I never see the problem. However, I had previously been able to use this application on another system, so I think there is some interaction going on, and that is what I am trying to tease out.

When I first run !uniqstack, there are only two threads that it shows in the DeviceLock process:

THREAD 88169650 Cid 03a8.01a4 Teb: 7ffda000 Win32Thread: 00000000 WAIT: (Executive) UserMode Non-Alertable
881ff6d4 NotificationEvent
IRP List:
8816bf68: (0006,0094) Flags: 00000070 Mdl: 00000000
Not impersonating
DeviceMap e10010b8
Owning Process 0 Image:
Attached Process 881f1698 Image: DLService.exe
Wait Start TickCount 1552 Ticks: 4264434 (0:18:30:31.781)
Context Switch Count 122
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address 0x0042569a
Start Address 0x7c8106f9
Stack Init a07d4000 Current a07d3bf0 Base a07d4000 Limit a07d1000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 16
Kernel stack not resident.
ChildEBP RetAddr Args to Child
a07d3c08 80503850 881696c0 88169650 804fb078 nt!KiSwapContext+0x2f (FPO: [Uses EBP] [0,0,4])
a07d3c14 804fb078 00000103 00000000 8816bf68 nt!KiSwapThread+0x8a (FPO: [0,0,0])
a07d3c3c 8057f9fa 00000001 00000000 00000001 nt!KeWaitForSingleObject+0x1c2 (FPO: [Non-Fpo])
a07d3c64 805807f7 89cc0428 00000103 881ff678 nt!IopSynchronousServiceTail+0xe8 (FPO: [Non-Fpo])
a07d3d00 80579274 00000268 00000000 00000000 nt!IopXxxControlFile+0x5c5 (FPO: [Non-Fpo])
a07d3d34 8054163c 00000268 00000000 00000000 nt!NtDeviceIoControlFile+0x2a (FPO: [Non-Fpo])
a07d3d34 7c90e514 00000268 00000000 00000000 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ a07d3d64)
01c2ff68 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

THREAD 881a1b30 Cid 03a8.01a0 Teb: 7ffd8000 Win32Thread: 00000000 WAIT: (Executive) KernelMode Non-Alertable
9e1da774 SynchronizationEvent
881a1c20 NotificationTimer
IRP List:
88144538: (0006,0094) Flags: 00000000 Mdl: 00000000
Not impersonating
DeviceMap e10010b8
Owning Process 0 Image:
Attached Process 881f1698 Image: DLService.exe
Wait Start TickCount 4265979 Ticks: 7 (0:00:00:00.109)
Context Switch Count 612949
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address 0x00424867
Start Address 0x7c8106f9
Stack Init 9e1db000 Current 9e1da700 Base 9e1db000 Limit 9e1d8000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 16
ChildEBP RetAddr Args to Child
9e1da718 80503850 881a1ba0 881a1b30 804fb078 nt!KiSwapContext+0x2f (FPO: [Uses EBP] [0,0,4])
9e1da724 804fb078 9e1dab9c 881d2880 88144538 nt!KiSwapThread+0x8a (FPO: [0,0,0])
9e1da74c 9d0196d1 00000000 00000000 00000000 nt!KeWaitForSingleObject+0x1c2 (FPO: [Non-Fpo])
WARNING: Stack unwind information not available. Following frames may be wrong.
9e1da784 9d0243fe 9e1dab9c 881d2880 88144538 DeviceLockDriver0+0x236d1
9e1da7fc 9d017cdd 88144538 88144554 86697150 DeviceLockDriver0+0x2e3fe
9e1dac40 804ef19f 8807e788 88144538 806e6410 DeviceLockDriver0+0x21cdd
9e1dac50 8057f982 881445a8 86697150 88144538 nt!IopfCallDriver+0x31 (FPO: [0,0,0])
9e1dac64 805807f7 8807e788 88144538 86697150 nt!IopSynchronousServiceTail+0x70 (FPO: [Non-Fpo])
9e1dad00 80579274 000001f0 00000000 00000000 nt!IopXxxControlFile+0x5c5 (FPO: [Non-Fpo])
9e1dad34 8054163c 000001f0 00000000 00000000 nt!NtDeviceIoControlFile+0x2a (FPO: [Non-Fpo])
9e1dad34 7c90e514 000001f0 00000000 00000000 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ 9e1dad64)
01e2ff78 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

The first thread is waiting because it has sent a IOCTL_MOUNTMGR_CHANGE_NOTIFY to MountMgr. This seems legitimate to me (i.e., not a deadlock).

0: kd> !irp 8816bf68
Irp is active with 1 stacks 1 is current (= 0x8816bfd8)
No Mdl: System buffer=88201bb8: Thread 88169650: Irp stack trace.
cmd flg cl Device File Completion-Context
>[e, 0] 5 1 89cc0428 881ff678 00000000-00000000 pending
\Driver\MountMgr
Args: 00000004 00000004 006d4020 00000000

The second thread has sent an IOCTL to the DeviceLock driver. It is a black box and I have no idea if it is deadlocked or not.

0: kd> !irp 88144538
Irp is active with 1 stacks 1 is current (= 0x881445a8)
No Mdl: No System Buffer: Thread 881a1b30: Irp stack trace.
cmd flg cl Device File Completion-Context
>[e, 0] 5 0 8807e788 86697150 00000000-00000000
\Driver\DeviceLockDriver0
Args: 00000000 00008000 8779227f 010c0048

Is there anything to see in these two threads? I notice that the “Args to Child” on frame 1 are strikingly different. In the first thread we have what looks like a handle, null, then the IRP the thread is waiting for. For the second thread we have what looks like a location on the stack, something in the kernel memory area (?), and the IRP we are waiting for.

On the second run of uniqstack, there are 23 threads within the Device Lock process.

Thanks in advance again…

wrote in message news:xxxxx@windbg…
>When in the failed state, I ran !apexts.uniqstack and got 369 threads in
>the system but only 67 unique. Then I poked around >for a bit, including
>setting .process and .thread. After this, I ran !apexts.uniqstack again and
>got 369 threads but 131 unique. Is >this expected?

Yes, it’s expected. In the extension we don’t do a full user mode symbol
reload for each process, which means that if this is a full memory dump as
you switch around in processes and load user symbols you’ll find more and
more “unique” call chains (without user symbols loaded the call stacks walk
off the face of the planet). I played with loading user symbols for each
process but it took so long that it defeated the purpose of, “a quick way to
find interesting threads.” As is, you can think of it more as showing unique
kernel call stacks.

>The first thread is waiting because it has sent a
>IOCTL_MOUNTMGR_CHANGE_NOTIFY to MountMgr. This seems legitimate to >me
>(i.e., not a deadlock).

I’d say that’s correct. Don’t know much about that IOCTL, but it sounds like
the sort of thing that stays pending until some asynchronous event happens.

> Is there anything to see in these two threads?

The thing that jumps out the most in the second thread is that it’s only
been waiting for less than one second:

> Wait Start TickCount 4265979 Ticks: 7 (0:00:00:00.109)

So my guess would be that this is not an interesting thread and that if you
hit Go on the target this would have come back to life.

>I notice that the “Args to Child” on frame 1 are strikingly different. In
>the first thread we have what looks like a handle, null, >then the IRP the
>thread is waiting for. For the second thread we have what looks like a
>location on the stack, something in the >kernel memory area (?), and the
>IRP we are waiting for.

You have to be careful with the Args to Child, you can’t really put too much
faith in them without doing a lot of work to confirm that these are actually
arguments (more info can be found here: http://analyze-v.com/?p=7)

The !uniqstack output is probably a bit long for here, if you want to mail
it to me in a text file (snoone at osr dot com) I can report on the
potentially interesting bits.

-scott


Scott Noone
Consulting Associate
OSR Open Systems Resources, Inc.
http://www.osronline.com

wrote in message news:xxxxx@windbg…
> When in the failed state, I ran !apexts.uniqstack and got 369 threads in
> the system but only 67 unique. Then I poked around for a bit, including
> setting .process and .thread. After this, I ran !apexts.uniqstack again
> and got 369 threads but 131 unique. Is this expected?
>
> I do have a bit of a lead from trying to do some gross poking from the
> image side. If I call a process called Device Lock before trying to shut
> down, then I never see the problem. However, I had previously been able to
> use this application on another system, so I think there is some
> interaction going on, and that is what I am trying to tease out.
>
> When I first run !uniqstack, there are only two threads that it shows in
> the DeviceLock process:
>
> THREAD 88169650 Cid 03a8.01a4 Teb: 7ffda000 Win32Thread: 00000000 WAIT:
> (Executive) UserMode Non-Alertable
> 881ff6d4 NotificationEvent
> IRP List:
> 8816bf68: (0006,0094) Flags: 00000070 Mdl: 00000000
> Not impersonating
> DeviceMap e10010b8
> Owning Process 0 Image:
> Attached Process 881f1698 Image: DLService.exe
> Wait Start TickCount 1552 Ticks: 4264434 (0:18:30:31.781)
> Context Switch Count 122
> UserTime 00:00:00.000
> KernelTime 00:00:00.000
> Win32 Start Address 0x0042569a
> Start Address 0x7c8106f9
> Stack Init a07d4000 Current a07d3bf0 Base a07d4000 Limit a07d1000 Call 0
> Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 16
> Kernel stack not resident.
> ChildEBP RetAddr Args to Child
> a07d3c08 80503850 881696c0 88169650 804fb078 nt!KiSwapContext+0x2f (FPO:
> [Uses EBP] [0,0,4])
> a07d3c14 804fb078 00000103 00000000 8816bf68 nt!KiSwapThread+0x8a (FPO:
> [0,0,0])
> a07d3c3c 8057f9fa 00000001 00000000 00000001
> nt!KeWaitForSingleObject+0x1c2 (FPO: [Non-Fpo])
> a07d3c64 805807f7 89cc0428 00000103 881ff678
> nt!IopSynchronousServiceTail+0xe8 (FPO: [Non-Fpo])
> a07d3d00 80579274 00000268 00000000 00000000 nt!IopXxxControlFile+0x5c5
> (FPO: [Non-Fpo])
> a07d3d34 8054163c 00000268 00000000 00000000 nt!NtDeviceIoControlFile+0x2a
> (FPO: [Non-Fpo])
> a07d3d34 7c90e514 00000268 00000000 00000000 nt!KiFastCallEntry+0xfc (FPO:
> [0,0] TrapFrame @ a07d3d64)
> 01c2ff68 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet
> (FPO: [0,0,0])
>
> THREAD 881a1b30 Cid 03a8.01a0 Teb: 7ffd8000 Win32Thread: 00000000 WAIT:
> (Executive) KernelMode Non-Alertable
> 9e1da774 SynchronizationEvent
> 881a1c20 NotificationTimer
> IRP List:
> 88144538: (0006,0094) Flags: 00000000 Mdl: 00000000
> Not impersonating
> DeviceMap e10010b8
> Owning Process 0 Image:
> Attached Process 881f1698 Image: DLService.exe
> Wait Start TickCount 4265979 Ticks: 7 (0:00:00:00.109)
> Context Switch Count 612949
> UserTime 00:00:00.000
> KernelTime 00:00:00.000
> Win32 Start Address 0x00424867
> Start Address 0x7c8106f9
> Stack Init 9e1db000 Current 9e1da700 Base 9e1db000 Limit 9e1d8000 Call 0
> Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 16
> ChildEBP RetAddr Args to Child
> 9e1da718 80503850 881a1ba0 881a1b30 804fb078 nt!KiSwapContext+0x2f (FPO:
> [Uses EBP] [0,0,4])
> 9e1da724 804fb078 9e1dab9c 881d2880 88144538 nt!KiSwapThread+0x8a (FPO:
> [0,0,0])
> 9e1da74c 9d0196d1 00000000 00000000 00000000
> nt!KeWaitForSingleObject+0x1c2 (FPO: [Non-Fpo])
> WARNING: Stack unwind information not available. Following frames may be
> wrong.
> 9e1da784 9d0243fe 9e1dab9c 881d2880 88144538 DeviceLockDriver0+0x236d1
> 9e1da7fc 9d017cdd 88144538 88144554 86697150 DeviceLockDriver0+0x2e3fe
> 9e1dac40 804ef19f 8807e788 88144538 806e6410 DeviceLockDriver0+0x21cdd
> 9e1dac50 8057f982 881445a8 86697150 88144538 nt!IopfCallDriver+0x31 (FPO:
> [0,0,0])
> 9e1dac64 805807f7 8807e788 88144538 86697150
> nt!IopSynchronousServiceTail+0x70 (FPO: [Non-Fpo])
> 9e1dad00 80579274 000001f0 00000000 00000000 nt!IopXxxControlFile+0x5c5
> (FPO: [Non-Fpo])
> 9e1dad34 8054163c 000001f0 00000000 00000000 nt!NtDeviceIoControlFile+0x2a
> (FPO: [Non-Fpo])
> 9e1dad34 7c90e514 000001f0 00000000 00000000 nt!KiFastCallEntry+0xfc (FPO:
> [0,0] TrapFrame @ 9e1dad64)
> 01e2ff78 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet
> (FPO: [0,0,0])
>
>
> The first thread is waiting because it has sent a
> IOCTL_MOUNTMGR_CHANGE_NOTIFY to MountMgr. This seems legitimate to me
> (i.e., not a deadlock).
>
> 0: kd> !irp 8816bf68
> Irp is active with 1 stacks 1 is current (= 0x8816bfd8)
> No Mdl: System buffer=88201bb8: Thread 88169650: Irp stack trace.
> cmd flg cl Device File Completion-Context
>>[e, 0] 5 1 89cc0428 881ff678 00000000-00000000 pending
> \Driver\MountMgr
> Args: 00000004 00000004 006d4020 00000000
>
>
> The second thread has sent an IOCTL to the DeviceLock driver. It is a
> black box and I have no idea if it is deadlocked or not.
>
> 0: kd> !irp 88144538
> Irp is active with 1 stacks 1 is current (= 0x881445a8)
> No Mdl: No System Buffer: Thread 881a1b30: Irp stack trace.
> cmd flg cl Device File Completion-Context
>>[e, 0] 5 0 8807e788 86697150 00000000-00000000
> \Driver\DeviceLockDriver0
> Args: 00000000 00008000 8779227f 010c0048
>
>
> Is there anything to see in these two threads? I notice that the “Args to
> Child” on frame 1 are strikingly different. In the first thread we have
> what looks like a handle, null, then the IRP the thread is waiting for.
> For the second thread we have what looks like a location on the stack,
> something in the kernel memory area (?), and the IRP we are waiting for.
>
> On the second run of uniqstack, there are 23 threads within the Device
> Lock process.
>
> Thanks in advance again…
>