Huge ticks output in "!thread"

gaurav_bhandarkar · August 2, 2012, 2:36am

1>
the issue is a(my) driver hang

2>
the dump taken with notmyfault…

3>
my code is doing:-
KeDelayExecutionThread(KernelMode, FALSE, &vol_mem_wait)

where:-
xxx!vol_mem_wait
0xffffffffffffff9c +0x000 LowPart : 0xffffff9c +0x004 HighPart : 0n-1 +0x000 u : <unnamed-tag> +0x000 QuadPart : 0n-100 Now the thread calling "KeDelayExecutionThread" shows :- THREAD fffffa80097b1900 Cid 09d4.0e58 Teb: 000007fffff8c000 Win32Thread: 0000000000000000 WAIT: (Suspended) KernelMode Non-Alertable SuspendCount 1 FreezeCount 33 fffffa80097b1bd8 Semaphore Limit 0x2 IRP List: fffffa8007a51b70: (0006,0118) Flags: 00060070 Mdl: 00000000 Not impersonating DeviceMap fffff8a000008120 Owning Process fffffa8009556060 Image: xxxx.exe Attached Process N/A Image: N/A Wait Start TickCount 3748044 Ticks: 19489 (0:00:05:04.030) Context Switch Count 206612 UserTime 00:00:10.545 KernelTime 00:00:06.942 Win32 Start Address xxxx!xxxxxx::ConfigThreadStartup (0x00000000743c441c) Stack Init fffff88007a67db0 Current fffff88007a67230 Base fffff88007a68000 Limit fffff88007a62000 Call 0 Priority 10 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5 Child-SP RetAddr : Args to Child : Call Site fffff88007a67270 fffff80001ad8992 : fffffa80097b1900 fffffa80097b1900 0000000000000000 fffffa80097b1900 : nt!KiSwapContext+0x7a fffff88007a673b0 fffff80001adb1af : 0000000000000000 0000000000000000 fffffa8000000000 fffff80001ad5eda : nt!KiCommitThreadWait+0x1d2 fffff88007a67440 fffff80001ac60b4 : 0000000000000000 0000000000000005 0000000000000000 0000000000000000 : nt!KeWaitForSingleObject+0x19f fffff88007a674e0 fffff80001ac6d31 : fffffa80097b1900 fffffa80097b1950 0000000000000000 fffff88000000000 : nt!KiSuspendThread+0x54 fffff88007a67520 fffff80001ad8b9d : fffff88002be4ee0 0000000000000000 fffff80001ac6060 0000000000000000 : nt!KiDeliverApc+0x201 fffff88007a675a0 fffff80001ada1a2 : 0000000000000000 fffff88002a5d180 00000000000000cb 00000000047cff70 : nt!KiCommitThreadWait+0x3dd fffff88007a67630 fffff88001314b37 : 0000000000000000 fffffa80097b4b50 00000000047cff00 00000000`000000cb : nt!KeDelayExecutionThread+0x186

4>
Note the huge tick count

5> how is this possible ?

OSR_Community_User · August 2, 2012, 12:14pm

I am curious about one thing: I read the parameter as -10. which means 10
100ns units, or 1us. But that translates to 15ms on most systems, unless
you have set the timer resolution yourself (only for newer systems).

If you only need a 1us delay, KeStallExecutionProcessor(1) is the better
choice.
joe

1>
the issue is a(my) driver hang

2>
the dump taken with notmyfault…

3>
my code is doing:-
KeDelayExecutionThread(KernelMode, FALSE, &vol_mem_wait)

where:-
xxx!vol_mem_wait
0xffffffffffffff9c +0x000 LowPart : 0xffffff9c +0x004 HighPart : 0n-1 +0x000 u : <unnamed-tag> > +0x000 QuadPart : 0n-100 > > > Now the thread calling "KeDelayExecutionThread" shows :- > THREAD fffffa80097b1900 Cid 09d4.0e58 Teb: 000007fffff8c000 Win32Thread: > 0000000000000000 WAIT: (Suspended) KernelMode Non-Alertable > SuspendCount 1 > FreezeCount 33 > fffffa80097b1bd8 Semaphore Limit 0x2 > IRP List: > fffffa8007a51b70: (0006,0118) Flags: 00060070 Mdl: 00000000 > Not impersonating > DeviceMap fffff8a000008120 > Owning Process fffffa8009556060 Image: xxxx.exe > Attached Process N/A Image: N/A > Wait Start TickCount 3748044 Ticks: 19489 (0:00:05:04.030) > Context Switch Count 206612 > UserTime 00:00:10.545 > KernelTime 00:00:06.942 > Win32 Start Address xxxx!xxxxxx::ConfigThreadStartup (0x00000000743c441c) > Stack Init fffff88007a67db0 Current fffff88007a67230 > Base fffff88007a68000 Limit fffff88007a62000 Call 0 > Priority 10 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 > PagePriority 5 > Child-SP RetAddr : Args to Child > : Call Site > fffff88007a67270 fffff80001ad8992 : fffffa80097b1900 fffffa80097b1900 > 0000000000000000 fffffa80097b1900 : nt!KiSwapContext+0x7a > fffff88007a673b0 fffff80001adb1af : 0000000000000000 0000000000000000 > fffffa8000000000 fffff80001ad5eda : nt!KiCommitThreadWait+0x1d2 > fffff88007a67440 fffff80001ac60b4 : 0000000000000000 0000000000000005 > 0000000000000000 0000000000000000 : nt!KeWaitForSingleObject+0x19f > fffff88007a674e0 fffff80001ac6d31 : fffffa80097b1900 fffffa80097b1950 > 0000000000000000 fffff88000000000 : nt!KiSuspendThread+0x54 > fffff88007a67520 fffff80001ad8b9d : fffff88002be4ee0 0000000000000000 > fffff80001ac6060 0000000000000000 : nt!KiDeliverApc+0x201 > fffff88007a675a0 fffff80001ada1a2 : 0000000000000000 fffff88002a5d180 > 00000000000000cb 00000000047cff70 : nt!KiCommitThreadWait+0x3dd > fffff88007a67630 fffff88001314b37 : 0000000000000000 fffffa80097b4b50 > 00000000047cff00 00000000`000000cb : nt!KeDelayExecutionThread+0x186
>
> 4>
> Note the huge tick count
>
> 5> how is this possible ?
>
> —
> WINDBG is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>

Tim_Roberts · August 2, 2012, 12:25pm

xxxxx@gmail.com wrote:

3>
my code is doing:-
KeDelayExecutionThread(KernelMode, FALSE, &vol_mem_wait)
…
Now the thread calling “KeDelayExecutionThread” shows :-
THREAD fffffa80097b1900 Cid 09d4.0e58 Teb: 000007fffff8c000 Win32Thread: 0000000000000000 WAIT: …
…
Child : Call Site
fffff88007a67270 fffff80001ad8992 : fffffa80097b1900 fffffa80097b1900 0000000000000000 fffffa80097b1900 : nt!KiSwapContext+0x7a
fffff88007a673b0 fffff80001adb1af : 0000000000000000 0000000000000000 fffffa8000000000 fffff80001ad5eda : nt!KiCommitThreadWait+0x1d2
fffff88007a67440 fffff80001ac60b4 : 0000000000000000 0000000000000005 0000000000000000 0000000000000000 : nt!KeWaitForSingleObject+0x19f
…4>
Note the huge tick count

5> how is this possible ?

You’re looking at the wrong code. That thread is in
KeWaitForSingleObject, not KeDelayExecutionThread.

–
Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

gaurav_bhandarkar · August 3, 2012, 1:33am

1>
nope… i have truncated the stack to show relevant things.

2>
Here is a more complete version of !thread output :

THREAD fffffa80097b1900 Cid 09d4.0e58 Teb: 000007fffff8c000 Win32Thread: 0000000000000000 WAIT: (Suspended) KernelMode Non-Alertable
SuspendCount 1
FreezeCount 33
fffffa80097b1bd8 Semaphore Limit 0x2
IRP List:
fffffa8007a51b70: (0006,0118) Flags: 00060070 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000008120
Owning Process fffffa8009556060 Image: xxxx.exe
Attached Process N/A Image: N/A
Wait Start TickCount 3748044 Ticks: 19489 (0:00:05:04.030)
Context Switch Count 206612
UserTime 00:00:10.545
KernelTime 00:00:06.942
Win32 Start Address 0x00000000743c441c
Stack Init fffff88007a67db0 Current fffff88007a67230
Base fffff88007a68000 Limit fffff88007a62000 Call 0
Priority 10 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP RetAddr : Args to Child : Call Site
fffff88007a67270 fffff80001ad8992 : fffffa80097b1900 fffffa80097b1900 0000000000000000 fffffa80097b1900 : nt!KiSwapContext+0x7a
fffff88007a673b0 fffff80001adb1af : 0000000000000000 0000000000000000 fffffa8000000000 fffff80001ad5eda : nt!KiCommitThreadWait+0x1d2
fffff88007a67440 fffff80001ac60b4 : 0000000000000000 0000000000000005 0000000000000000 0000000000000000 : nt!KeWaitForSingleObject+0x19f
fffff88007a674e0 fffff80001ac6d31 : fffffa80097b1900 fffffa80097b1950 0000000000000000 fffff88000000000 : nt!KiSuspendThread+0x54
fffff88007a67520 fffff80001ad8b9d : fffff88002be4ee0 0000000000000000 fffff80001ac6060 0000000000000000 : nt!KiDeliverApc+0x201
fffff88007a675a0 fffff80001ada1a2 : 0000000000000000 fffff88002a5d180 00000000000000cb 00000000047cff70 : nt!KiCommitThreadWait+0x3dd
fffff88007a67630 fffff88001314b37 : 0000000000000000 fffffa80097b4b50 00000000047cff00 00000000000000cb : nt!KeDelayExecutionThread+0x186
fffff88007a676a0 fffff88001314157 : 0000000000000000 fffff80001afce64 fffffa80097b4b50 0000000003bfea27 : xxx!xxx+0x4f [xxx @ 765]
<…snip…>

3>
This thread is actually an IOCTL(dispatch) from my usermode serivce
It is expected to take a lock(R/W lock) and wait/sleep till some count to fall to zero.

But as you can see when I “sleep” I never got woken up.

-Gaurav