Page fault from IRQL (0xD1)

This blog post is about an interesting dump file I came across on our forum.
So far an IRP was sent from the Logitech Webcam down the driver stack of the USB parent driver, and then the USB 3.0 host controller. The IRP was changing the power state of this device, and incurred a page fault at Dispatch IRQL, a big no no.

0: kd> .bugcheck
Bugcheck code 000000D1
Arguments ffffcf80`54cf8fc0 00000000`00000002 00000000`00000001 fffff801`8e00f82b

0: kd> knL
 # Child-SP          RetAddr           Call Site
00 fffff802`c44c34b8 fffff802`c2947e29 nt!KeBugCheckEx
01 fffff802`c44c34c0 fffff802`c29465c7 nt!KiBugCheckDispatch+0x69
02 fffff802`c44c3600 fffff801`8e00f82b nt!KiPageFault+0x247
03 fffff802`c44c3798 fffff801`8e00db02 USBXHCI!memcpy+0x2b
04 fffff802`c44c37a0 fffff801`8e00a3c9 USBXHCI!Control_ProcessTransferEventWithED1+0x212
05 fffff802`c44c3830 fffff802`c2862df9 USBXHCI!Interrupter_WdfEvtInterruptDpc+0x759
06 fffff802`c44c3920 fffff802`c2862687 nt!KiExecuteAllDpcs+0x289
07 fffff802`c44c3a70 fffff802`c293ffda nt!KiRetireDpcList+0xe7
08 fffff802`c44c3c60 00000000`00000000 nt!KiIdleLoop+0x5a

0: kd> !irp ffffe001ce52b720
Irp is active with 20 stacks 17 is current (= 0xffffe001ce52bc70)
 No Mdl: No System Buffer: Thread ffffe001cd3f5040:  Irp stack trace.  
     cmd  flg cl Device   File     Completion-Context
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
>[IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]                                      //IRP is pending here
            0  1 ffffe001ce3551f0 00000000 00000000-00000000    pending
	       \Driver\USBXHCI
			Args: ffffcf8055ec2f60 00000000 00220003 ffffe001ce4e14e0
 [IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]
            0 e0 ffffe001ce3fae20 00000000 00000000-00000000    
	       \Driver\USBXHCI
			Args: ffffcf8055ec2f60 00000000 00220003 ffffe001ce4e14e0
 [IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]
            0 e1 ffffe001ce3fae20 00000000 00000000-00000000    pending
	       \Driver\USBXHCI
			Args: ffffcf8055ec2f60 00000000 00220003 ffffe001ce4e14e0
 [IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]
            0 e0 ffffe001ce4c0380 00000000 fffff8018ef6284c-ffffd00020b9bdb0 Success Error Cancel 
	      Page 104099 not present in the dump file. Type ".hh dbgerr004" for details
 \Driver\USBHUB3	lvuvc64!calloc
			Args: ffffcf8055ec2f60 00000000 00220003 ffffe001ce4e14e0

0: kd> !devstack ffffe001ce4e5b20
  !DevObj           !DrvObj            !DevExt           ObjectName
  ffffe001ce4e6060  \Driver\ksthunk    ffffe001ce4e61b0  00000049
> ffffe001ce4e5b20  \Driver\LVUVC64    ffffe001ce4e5c90  
  ffffe001ce4e3060  \Driver\usbccgp    ffffe001ce4e31b0  00000047
!DevNode ffffe001ce4e2880 :
  DeviceInst is "USB\VID_046D&PID_09A1&MI_00\7&12e6e5da&0&0000"
  ServiceName is "LVUVC64" // Logitech USB camera

0: kd> !devstack ffffe001ce4c0380
  !DevObj           !DrvObj            !DevExt           ObjectName
  ffffe001ce4cb060  \Driver\usbccgp    ffffe001ce4cb1b0  00000046
> ffffe001ce4c0380  \Driver\USBHUB3    ffffe001ce4bf850  USBPDO-9
!DevNode ffffe001ce4c4010 :
  DeviceInst is "USB\VID_046D&PID_09A1\B5471720"
  ServiceName is "usbccgp" //USB generic parent driver

0: kd> !drvobj \Driver\USBHUB3 //USB 3.0 hub driver object
Driver object (ffffe001ce776ac0) is for:
 \Driver\USBHUB3
Driver Extension List: (id , addr)
(fffff8018b13e0b0 ffffe001cf247150)  
Device Object list:
ffffe001ce530060  ffffe001ce52b060  ffffe001ce4c6e20  ffffe001ce4c0380
ffffe001ce4bee20  ffffe001ce422310  ffffe001ceed5cb0  ffffe001ceec5d50
ffffe001ceed6060  ffffe001cf3eba00  //All the attached devices, including the USB 3.0 Host Controller

//Memory referenced

0: kd> !pte ffffcf8054cf8fc0
                                           VA ffffcf8054cf8fc0
PXE at FFFFF6FB7DBEDCF8    PPE at FFFFF6FB7DB9F008    PDE at FFFFF6FB73E01530    PTE at FFFFF6E7C02A67C0
contains 0000000004D18863  contains 0000000100017863  contains 0000000100131863  contains 800000010A7B9882
pfn 4d18      ---DA--KWEV  pfn 100017    ---DA--KWEV  pfn 100131    ---DA--KWEV  not valid
                                                                                  Transition: 10a7b9 //Transition page, meaning it is still valid, but paged out from the working set
                                                                                  Protect: 4 - ReadWrite

0: kd> !pfn 10a7b9
    PFN 0010A7B9 at address FFFFFA80031F72B0
    flink       0010B6B3  blink / share count 000034BE  pteaddress FFFFF6E7C02A67C0
nt!_MMPFNENTRY type not found
    reference count 0000    used entry count  0000      NonCached color 0   Priority 0
    restore pte 00000080  containing page        100131  nt!_MMPFNENTRY type not found //Not exactly helpful

0: kd> knL
  *** Stack trace for last set context - .thread/.cxr resets it
 # Child-SP          RetAddr           Call Site
00 ffffd000`20b9b970 fffff802`c2868fcf nt!KiSwapContext+0x76
01 ffffd000`20b9bab0 fffff802`c2868aa3 nt!KiSwapThread+0x15f
02 ffffd000`20b9bb70 fffff802`c2868727 nt!KiCommitThreadWait+0x153
03 ffffd000`20b9bc10 fffff802`c2eca2ea nt!KeWaitForSingleObject+0x387
04 ffffd000`20b9bcc0 fffff802`c2ec9876 nt!ViKeWaitForSingleObjectCommon+0x92
05 ffffd000`20b9bd10 fffff801`8ef4dfef nt!VerifierKeWaitForSingleObject+0x1e
06 ffffd000`20b9bd50 fffff801`8ef4e981 lvuvc64!calloc+0x2d6a3
07 ffffd000`20b9be30 fffff801`8ef4ed4a lvuvc64!calloc+0x2e035
08 ffffd000`20b9beb0 fffff801`8ef4cc2f lvuvc64!calloc+0x2e3fe
09 ffffd000`20b9bf60 fffff801`8ef5ee30 lvuvc64!calloc+0x2c2e3
0a ffffd000`20b9bfb0 fffff801`8ef757d5 lvuvc64!calloc+0x3e4e4
0b ffffd000`20b9bfe0 fffff801`8ef739d4 lvuvc64!cvSetErrMode+0x21cd
0c ffffd000`20b9c040 fffff801`8ef748c3 lvuvc64!cvSetErrMode+0x3cc
0d ffffd000`20b9c0c0 fffff801`8ef36475 lvuvc64!cvSetErrMode+0x12bb
0e ffffd000`20b9c130 fffff801`8ef37e43 lvuvc64!calloc+0x15b29
0f ffffd000`20b9c1c0 fffff801`8ef38239 lvuvc64!calloc+0x174f7
10 ffffd000`20b9c260 fffff801`8ef205f1 lvuvc64!calloc+0x178ed
11 ffffd000`20b9c2f0 fffff801`8ed8b568 lvuvc64+0x5f1
Page 102418 not present in the dump file. Type ".hh dbgerr004" for details
12 ffffd000`20b9c320 fffff801`8ed82334 ks!CKsDevice::PnpStart+0x8794
Page 102418 not present in the dump file. Type ".hh dbgerr004" for details
Page 10248f not present in the dump file. Type ".hh dbgerr004" for details
13 ffffd000`20b9c370 fffff801`8ef616c4 ks!CKsDevice::DispatchPnp+0x104
Page 10248f not present in the dump file. Type ".hh dbgerr004" for details
14 ffffd000`20b9c3e0 fffff801`8b05e030 lvuvc64!calloc+0x40d78
15 ffffd000`20b9c410 fffff802`c2eb7eb6 VerifierExt!xdv_IRP_MJ_PNP_wrapper+0xe0
16 ffffd000`20b9c470 fffff802`c2858ff2 nt!IovCallDriver+0x252
17 ffffd000`20b9c4b0 fffff801`8cd514b1 nt!IofCallDriver+0x72
18 ffffd000`20b9c4f0 fffff802`c2eb7eb6 ksthunk!CKernelFilterDevice::DispatchIrp+0xf9
19 ffffd000`20b9c550 fffff802`c2858ff2 nt!IovCallDriver+0x252
1a ffffd000`20b9c590 fffff802`c2c201e9 nt!IofCallDriver+0x72
1b ffffd000`20b9c5d0 fffff802`c2822c68 nt!PnpAsynchronousCall+0xe5
1c ffffd000`20b9c610 fffff802`c2822790 nt!PnpSendIrp+0x54
1d ffffd000`20b9c680 fffff802`c2c1f4f7 nt!PnpStartDevice+0x88
1e ffffd000`20b9c710 fffff802`c2c1f153 nt!PnpStartDeviceNode+0xdb
1f ffffd000`20b9c7a0 fffff802`c2c08162 nt!PipProcessStartPhase1+0x53
20 ffffd000`20b9c7e0 fffff802`c2bfe745 nt!PipProcessDevNodeTree+0x402
21 ffffd000`20b9ca60 fffff802`c28eb802 nt!PiProcessReenumeration+0xa1
22 ffffd000`20b9cab0 fffff802`c284f1e9 nt!PnpDeviceActionWorker+0x166
23 ffffd000`20b9cb80 fffff802`c2807d85 nt!ExpWorkerThread+0xe9
24 ffffd000`20b9cc10 fffff802`c2942366 nt!PspSystemThreadStartup+0x41
25 ffffd000`20b9cc60 00000000`00000000 nt!KiStartSystemThread+0x16


Irp worker threads (PopIrpThreadList - fffff802c2add0c0)
  THREAD: ffffe001cbb05040 (static)
  THREAD: ffffe001cbb04040 (static)


//The thread we saw was indeed an IRP worker thread.

0: kd> !podev ffffe001ce4e5b20
Device object is for:
  DriverObject ce4db930
Current Irp 00000000 RefCount 0 Type 0000002f AttachedDev ffffe001ce4e6060 DevFlags 00002000  DO_POWER_PAGABLE //IRP flag indicating the device is pagable
Device queue is not busy.
Device Object Extension: ffffe001ce4e5c98:
PowerFlags: 00000000 =>SystemState=0 DeviceState=0
Dope: 00000000:

Out of curiosity there was another thread waiting on the PnP power management resource, waiting for our worker thread to release it. But it never did when the system crashed as a result of accessing the pageable memory.

Resource @ nt!PiEngineLock (0xfffff802c2afa320)    Exclusively owned
    Contention Count = 1
    NumberOfExclusiveWaiters = 1
     Threads: ffffe001cd3f5040-01<*> 
     Threads Waiting On Exclusive Access:
              ffffe001cbb9d040       

0: kd> !thread ffffe001cbb9d040 
THREAD ffffe001cbb9d040  Cid 0004.00a0  Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (WrResource) KernelMode Non-Alertable
    ffffe001ce362110  SynchronizationEvent
Not impersonating
DeviceMap                 ffffc0002b2180a0
Owning Process            ffffe001cba64700       Image:         System
Attached Process          N/A            Image:         N/A
Wait Start TickCount      158            Ticks: 254 (0:00:00:03.968)
Context Switch Count      1412           IdealProcessor: 1             
UserTime                  00:00:00.000
KernelTime                00:00:00.187
Win32 Start Address nt!ExpWorkerThread (0xfffff802c284f100)
Stack Init ffffd00020788c90 Current ffffd00020788640
Base ffffd00020789000 Limit ffffd00020783000 Call 0
Priority 12 BasePriority 12 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           : Args to Child                                                           : Call Site
ffffd000`20788680 fffff802`c2868fcf : ffffe001`00000000 ffffe001`cbb9d140 00000000`00000000 00000000`7a5b5a00 : nt!KiSwapContext+0x76
ffffd000`207887c0 fffff802`c2868aa3 : ffffe001`cbb9d040 ffffe001`cbb9d180 ffffe001`cbb9d140 00000000`00000000 : nt!KiSwapThread+0x15f
ffffd000`20788880 fffff802`c2868727 : 00000000`00000000 00000000`00000000 00000000`000000f7 00000000`00000000 : nt!KiCommitThreadWait+0x153
ffffd000`20788920 fffff802`c285507e : ffffe001`ce362110 ffffe001`0000001b 00000000`00000700 00000000`00000002 : nt!KeWaitForSingleObject+0x387
ffffd000`207889d0 fffff802`c28721ad : fffff802`c2afa320 ffffe001`ce362110 ffffe001`00000001 fffff802`00010224 : nt!ExpWaitForResource+0xde
ffffd000`20788a60 fffff802`c2c0873b : 00000000`00000002 ffffe001`cbb9d001 fffff802`c2cfab74 00000000`00000000 : nt!ExAcquireResourceExclusiveLite+0x17d
ffffd000`20788ad0 fffff802`c291110c : ffffe001`cbb9d040 fffff802`c2ad18f8 ffffe001`00000000 fffff802`c2cd74c8 : nt!PpDevNodeLockTree+0xd3
ffffd000`20788b00 fffff802`c2cfab91 : ffffe001`ce356230 00000000`00000000 00000000`00000200 fffff802`c2b97340 : nt!PnpLockDeviceActionQueue+0x10
ffffd000`20788b40 fffff802`c284f1e9 : ffffe001`cbb9d040 fffff802`c2ad8600 fffff801`00000000 ffffe001`63734943 : nt!WmipRegistrationWorker+0x1d
ffffd000`20788b80 fffff802`c2807d85 : 00000000`00000000 00000000`00000080 ffffe001`cba64700 ffffe001`cbb9d040 : nt!ExpWorkerThread+0xe9
ffffd000`20788c10 fffff802`c2942366 : fffff802`c2b20180 ffffe001`cbb9d040 fffff802`c2807d44 00000000`00000000 : nt!PspSystemThreadStartup+0x41
ffffd000`20788c60 00000000`00000000 : ffffd000`20789000 ffffd000`20783000 00000000`00000000 00000000`00000000 : nt!KiStartSystemThread+0x16


0: kd> !object ffffe001ce362110
Object: ffffe001ce362110  Type: (ffffe001cbb08b00) WaitCompletionPacket
    ObjectHeader: ffffe001ce3620e0 (new version)
    HandleCount: 18446735284269158576  PointerCount: 18446735284269281792 

 

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s