Software Diagnostics Library

It was reported that a system had an abnormally high number of interrupt activity visible in various monitoring tools. A complete memory dump was collected. When we open it and look at an IRP list we find statistically higher number of IRPs belonging to Disk and DriverA device drivers:

0: kd> !irpfind
Irp [ Thread ] irpStack: (Mj,Mn) DevObj [Driver] MDL Process
[…]
8a3d3008 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [ \Driver\Disk] 0×00000000
8a3d3340 [8acab888] irpStack: ( 3, 0) 8b4c6030 [ \FileSystem\Npfs]
8a3d4580 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [ \Driver\Disk] 0×00000000
8a403e00 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [ \Driver\Disk] 0×00000000
8a4047e0 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [ \Driver\Disk] 0×00000000
[…]
8aa6ab28 [00000000] irpStack: ( f, 0) 8b192030 [ \Driver\DriverA] 0×00000000
8aa6ce28 [00000000] irpStack: ( f, 0) 8b192030 [ \Driver\DriverA] 0×00000000
[…]

What we also notice is that the thread 8b56cb10 is also an active running thread so we look at its raw stack to find any executon residue providing hints to possible hardware activity.

0: kd> !stacks
Proc.Thread  .Thread  Ticks   ThreadState Blocker
                            [8b57f7a8 System]
   4.000070  8b579db0 ffffff42 Blocked    +0x1
   4.0000c0  8b5768d0 ffffff42 READY      nt!KiAdjustQuantumThread+0x109
   4.0000e4  8b56cb10 ffffff42 RUNNING    +0xf6fb2044
[…]

0: kd> !thread 8b56cb10
THREAD 8b56cb10  Cid 0004.00e4  Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 0
Not impersonating
DeviceMap                 e10018b8
Owning Process            8b57f7a8       Image:         System
Attached Process          N/A            Image:         N/A
Wait Start TickCount      24437735    
Context Switch Count      33644            
UserTime                  00:00:00.000
KernelTime                00:00:07.843
Start Address nt!MiMappedPageWriter (0x80847ffe)
Stack Init f70c4000 Current f70c3468 Base f70c4000 Limit f70c1000 Call 0
Priority 17 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr  Args to Child             
f70c3470 00000000 000000be e1912bc0 e1912bc4 0xf6fb2044

However, WinDbg reports another current thread running on the same processor so we obviously have an inconsistent dump and should exercise caution:

0: kd> !thread
THREAD 8089d8c0  Cid 0000.0000  Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 0
Not impersonating
Owning Process            8089db40       Image:         Idle
Attached Process          N/A            Image:         N/A
Wait Start TickCount      24437476       Ticks: 69 (0:00:00:01.078)
Context Switch Count      72194391            
UserTime                  00:00:00.000
KernelTime                4 Days 08:57:56.171
Stack Init 8089a8b0 Current 8089a5fc Base 8089a8b0 Limit 808978b0 Call 0
Priority 0 BasePriority 0 PriorityDecrement 0
ChildEBP RetAddr  Args to Child             
f3b30c5c 00000000 00000000 00000000 00000000 LiveKdD+0×1c07

0: kd> !running
[...]
Prcbs  Current   Next   
  0    ffdff120  8089d8c0            …………….
  1    f772f120  f7732090            …………….

0: kd> !thread f7732090
THREAD f7732090  Cid 0000.0000  Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 1
Not impersonating
Owning Process            8089db40       Image:         Idle
Attached Process          N/A            Image:         N/A
Wait Start TickCount      0              Ticks: 24437545 (4:10:03:56.640)
Context Switch Count      75624870            
UserTime                  00:00:00.000
KernelTime                4 Days 08:56:05.125
Stack Init f78b3000 Current f78b2d4c Base f78b3000 Limit f78b0000 Call 0
Priority 0 BasePriority 0 PriorityDecrement 0
ChildEBP RetAddr  Args to Child             
f3b30c5c 00000000 00000000 00000000 00000000 LiveKdD+0×1c07

Let’s come back to the thread 8b56cb10. Its raw stack residue shows traces of SCSI activity:

0: kd> dps f70c1000 f70c4000
[...]
f70c2f38  8b20100c
f70c2f3c  f70c2f9c
f70c2f40  f72922a5 DriverA!BuildScatterGather+0×9b
f70c2f44  8b20100c
f70c2f48  8aa24dfc
[…]
f70c337c  00000000
f70c3380  00000246
f70c3384  808a6228 nt!KiProcessorBlock+0×8
f70c3388  00000002
f70c338c  00000011
f70c3390  00000246
f70c3394  f70c33a4
f70c3398  80a62a73 hal!HalRequestIpi+0×13
f70c339c  00000002
f70c33a0  000000e1
f70c33a4  f70c33dc
f70c33a8  8082e4db nt!KiIpiSend+0×27
f70c33ac  00000002
f70c33b0  f772fa7c
f70c33b4  8b56bdb0
f70c33b8  ffdff120
f70c33bc  00000000
f70c33c0  00000002
f70c33c4  00000001
f70c33c8  00000000
f70c33cc  00000002
f70c33d0  00000002
f70c33d4  f70c33e4
f70c33d8  80a61456 hal!KfLowerIrql+0×62
f70c33dc  00000001
f70c33e0  00000002
f70c33e4  f70c3494
f70c33e8  f70c3450
f70c33ec  8b56cb10
f70c33f0  8b089100
f70c33f4  8a5abe01
f70c33f8  f70c3450
f70c33fc  8b089100
f70c3400  8a5abe01
f70c3404  8b089101
f70c3408  f70c3418
f70c340c  80a61456 hal!KfLowerIrql+0×62
f70c3410  8a5abe98
f70c3414  8b089101
f70c3418  f70c3450
f70c341c  f70c3434
f70c3420  80819c10 nt!FsFilterPerformCompletionCallbacks+0×2e
f70c3424  f70c3450
f70c3428  00000000
f70c342c  00000000
f70c3430  00000000
f70c3434  f70c3584
f70c3438  f70c3584
f70c343c  80815040 nt!FsRtlReleaseFileForModWrite+0×190
f70c3440  f70c3450
f70c3444  8b56cdc4
f70c3448  00010000
f70c344c  8b56cd68
f70c3450  00000024
f70c3454  8b56cbfc
f70c3458  8abe10f0
f70c345c  8a5b4830
f70c3460  8b089100
f70c3464  80a613f4 hal!KfLowerIrql
f70c3468  00000001
f70c346c  00000246
f70c3470  f6fb2044
f70c3474  00000000
f70c3478  000000be
f70c347c  e1912bc0
f70c3480  e1912bc4
f70c3484  8a4b7db8
f70c3488  00000011
f70c348c  f70c34a4
f70c3490  8081610e nt!FsRtlLookupBaseMcbEntry+0×16
f70c3494  80887b75 nt!KiFlushTargetSingleTb+0xd
f70c3498  f70c34d0
f70c349c  8082e431 nt!KiIpiServiceRoutine+0×4d
f70c34a0  f772f121
f70c34a4  00000000
f70c34a8  e2894000
f70c34ac  00000000
f70c34b0  80872322 nt!WRITE_REGISTER_ULONG+0xa
f70c34b4  8b20100c
f70c34b8  80a6157e hal!HalEndSystemInterrupt+0×6e
f70c34bc  8b20100c
f70c34c0  f70c34d0
f70c34c4  80a5e902 hal!HalpIpiHandler+0xd2
f70c34c8  80816209 nt!FsRtlLookupLargeMcbEntry+0×4d
f70c34cc  000000e1
f70c34d0  f70c3564
f70c34d4  80872322 nt!WRITE_REGISTER_ULONG+0xa
f70c34d8  badb0d00
f70c34dc  f6fb2040
f70c34e0  8b20100c
f70c34e4  8b038fb4
f70c34e8  0000f000
f70c34ec  f70c3510
f70c34f0  8b377e10
f70c34f4  8b20100c
f70c34f8  8b038fb4
f70c34fc  00000000
f70c3500  00000000
f70c3504  8b377e64
f70c3508  00000007
f70c350c  f6fb2040
f70c3510  8b201100
f70c3514  0b377e10
f70c3518  00000005
f70c351c  ffdff120
f70c3520  ffdffa40
f70c3524  8b4eca09
f70c3528  8b20100c
f70c352c  ffdffa40
f70c3530  8b4eca09
f70c3534  ffdffa09
f70c3538  f70c3548
f70c353c  80a61456 hal!KfLowerIrql+0×62
f70c3540  8b4ecab4
f70c3544  ffdffa09
f70c3548  f70c356c
f70c354c  80829f70 nt!KeInsertQueueDpc+0×1c4
f70c3550  8b4ecaf8
f70c3554  8b038fb4
f70c3558  8b192001
f70c355c  ffdffa48
f70c3560  ffdff120
f70c3564  00000000
f70c3568  01092855
f70c356c  f70c3580
f70c3570  f727221d SCSIPORT!SpRequestCompletionDpc+0×2d
f70c3574  014ecab4
f70c3578  8b4ecab8
f70c357c  8b4ecaf8
f70c3580  8b4ecbf8
f70c3584  00000102
f70c3588  8b4eca40
f70c358c  8b4ecaf8
f70c3590  8b4ecbf8
f70c3594  8b038f02
f70c3598  f70c35a8
f70c359c  8b4ecbf8
f70c35a0  8b038f02
f70c35a4  8b4ecb02
f70c35a8  f70c35b8
f70c35ac  80a61456 hal!KfLowerIrql+0×62
f70c35b0  8b038f02
f70c35b4  8b4ecb02
f70c35b8  f70c35d8
f70c35bc  80a5f44b hal!KfReleaseSpinLock+0xb
f70c35c0  f72737ae SCSIPORT!SpReceiveScatterGather+0×33b
f70c35c4  8b56bb94
f70c35c8  00000000
f70c35cc  0cd8e000
f70c35d0  0000000f
f70c35d4  0000000f
f70c35d8  f70c3604
f70c35dc  80a60147 hal!HalBuildScatterGatherList+0×1c7
f70c35e0  8b4eca40
f70c35e4  8a5acd20
f70c35e8  8ab7aa98
f70c35ec  8ab7aa30
f70c35f0  8a5acd20
f70c35f4  8b4ecaf8
f70c35f8  8b038fb4
f70c35fc  00804001
f70c3600  00000000
f70c3604  f70c3650
f70c3608  f72733a6 SCSIPORT!ScsiPortStartIo+0×36a
f70c360c  8ab7aa98
f70c3610  8b4eca40
f70c3614  8b56bb38
f70c3618  00000000
f70c361c  00010000
f70c3620  f72736b4 SCSIPORT!SpReceiveScatterGather
f70c3624  8ab7aa30
f70c3628  00000000
f70c362c  8b4eca40
f70c3630  8a5acd20
f70c3634  00000002
f70c3638  8b4eca40
f70c363c  f70c39e0
f70c3640  f70c3658
f70c3644  00000000
f70c3648  80a611ae hal!HalpDispatchSoftwareInterrupt+0×5e
f70c364c  00000000
f70c3650  8a5acd00
f70c3654  00000202
f70c3658  f70c3674
f70c365c  80a613d9 hal!HalpCheckForSoftwareInterrupt+0×81
f70c3660  8b4ecb02
f70c3664  00000000
f70c3668  8b1920e8
f70c366c  8a5acd00
f70c3670  8b4ecb02
f70c3674  f70c3684
f70c3678  80a61456 hal!KfLowerIrql+0×62
f70c367c  8a5acd20
f70c3680  8b4ecb00
f70c3684  f70c36a8
f70c3688  f7273638 SCSIPORT!ScsiPortFdoDispatch+0×279
f70c368c  8b4ecaf8
f70c3690  8b41a228
f70c3694  8a5acd20
f70c3698  f70c36d0
f70c369c  f70c36ac
f70c36a0  8ab7aa30
f70c36a4  8b1920e8
f70c36a8  f70c36c4
f70c36ac  f7273146 SCSIPORT!SpDispatchRequest+0×68
f70c36b0  8b4eca40
f70c36b4  005acdb4
f70c36b8  8b038fb4
f70c36bc  8b1920e8
f70c36c0  8a5acd20
f70c36c4  f70c36e0
f70c36c8  f7272dc3 SCSIPORT!ScsiPortPdoScsi+0×129
f70c36cc  8b1920e8
f70c36d0  8a5acd20
f70c36d4  8a581008
f70c36d8  8a5acd20
f70c36dc  8b192030
f70c36e0  f70c36f4
f70c36e4  f7272299 SCSIPORT!ScsiPortGlobalDispatch+0×1d
f70c36e8  8b192030
f70c36ec  8a5acd20
f70c36f0  8b5441c8
f70c36f4  f70c3708
f70c36f8  8081df85 nt!IofCallDriver+0×45
f70c36fc  8b192030
f70c3700  8a5acd20
f70c3704  8b038f08
f70c3708  f70c3718
f70c370c  f725f607 CLASSPNP!SubmitTransferPacket+0xbb
f70c3710  8b038f08
f70c3714  00000000
f70c3718  f70c374c
f70c371c  f725f2b2 CLASSPNP!ServiceTransferRequest+0×1e4
f70c3720  8b038f08
f70c3724  8b1b80e8
f70c3728  8a581150
f70c372c  8a581008
f70c3730  24052000
f70c3734  00000001
f70c3738  00000001
f70c373c  00011000
f70c3740  00010000
f70c3744  00000000
f70c3748  00000001
f70c374c  f70c3770
f70c3750  f725f533 CLASSPNP!ClassReadWrite+0×159
f70c3754  00000103
f70c3758  00000000
f70c375c  8a581008
f70c3760  8b57e218
f70c3764  8b055790
f70c3768  8b192030
f70c376c  00010000
f70c3770  f70c3784
f70c3774  8081df85 nt!IofCallDriver+0×45
f70c3778  8b1b8030
f70c377c  00000103
f70c3780  8b51d1c8
f70c3784  f70c3794
f70c3788  f74c80cf PartMgr!PmReadWrite+0×95
f70c378c  8b467e00
f70c3790  8a581174
f70c3794  f70c37a8
f70c3798  8081df85 nt!IofCallDriver+0×45
f70c379c  8b0556d8
f70c37a0  8a581008
f70c37a4  8a581198
f70c37a8  f70c37c4
f70c37ac  f7317053 ftdisk!FtDiskReadWrite+0×1a9
f70c37b0  8a5811b4
f70c37b4  8b5570c8
f70c37b8  8b201c40
f70c37bc  24032000
f70c37c0  8b467d48
f70c37c4  f70c37d8
f70c37c8  8081df85 nt!IofCallDriver+0×45
f70c37cc  8b467d48
f70c37d0  8a581008
f70c37d4  8a5811d8
f70c37d8  f70c37f8
f70c37dc  f72c0537 volsnap!VolSnapWrite+0×46f
f70c37e0  8a581008
f70c37e4  8b5851c8
f70c37e8  e25b3668
f70c37ec  fd800000
f70c37f0  8b201c40
f70c37f4  00000002
f70c37f8  f70c380c
f70c37fc  8081df85 nt!IofCallDriver+0×45
f70c3800  8b201b88
f70c3804  8a581008
[…]

There’s past DPC insertion activity but no pending DPCs:

0: kd> ub 80829f70
nt!KeInsertQueueDpc+0x1a9:
80829f55 6a02            push    2
80829f57 5a              pop     edx
80829f58 e857450000      call    nt!KiIpiSend (8082e4b4)
80829f5d eb08            jmp     nt!KeInsertQueueDpc+0x1bb (80829f67)
80829f5f b102            mov     cl,2
80829f61 ff1598108080    call    dword ptr [nt!_imp_HalRequestSoftwareInterrupt (80801098)]
80829f67 8a4dfe          mov     cl,byte ptr [ebp-2]
80829f6a ff1508118080    call    dword ptr [nt!_imp_KfLowerIrql (80801108)]

0: kd> !dpcs
CPU Type      KDPC       Function

dpcs: no pending DPCs found

We notice DriverA and see it also attached to Disk driver device:

0: kd> !irp 8a3d3008
Irp is active with 11 stacks 7 is current (= 0x8a3d3150)
 Mdl=8b56b6a0: No System Buffer: Thread 8b56cb10:  Irp stack trace. 
     cmd  flg cl Device   File     Completion-Context
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   
   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   
   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   
   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   
   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   
   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000   
   Args: 00000000 00000000 00000000 00000000
>[  4,34]   0 e0 8b1b8030 00000000 f74c857e-8b0556d8 Success Error Cancel
        \Driver\Disk PartMgr!PmIoCompletion
   Args: 00010000 00000000 f457e000 00000002
 [  4, 0]   0 e1 8b0556d8 00000000 f7316558-8b467e00 Success Error Cancel pending
        \Driver\PartMgr ftdisk!FtpRefCountCompletionRoutine
   Args: 7274c6df 0002b74c f457e000 00000002
 [  4, 0]   0 e1 8b467d48 00000000 f72bf638-8b201c40 Success Error Cancel pending
        \Driver\Ftdisk volsnap!VspRefCountCompletionRoutine
   Args: 7274c5f4 0002b74c f456e000 00000002
 [  4, 0]   0 e1 8b201b88 00000000 f71814e8-8b206238 Success Error Cancel pending
        \Driver\VolSnap Ntfs!NtfsSingleAsyncCompletionRoutine
   Args: 00010000 00000000 f456e000 00000002
 [  4, 0]   0  0 8b36b020 8a5b4830 00000000-00000000   
        \FileSystem\Ntfs
   Args: 00010000 00000000 08710000 00000000

0: kd> !devobj 8b1b8030
Device object (8b1b8030) is for:
 DR0 \Driver\Disk DriverObject 8b57e218
Current Irp 00000000 RefCount 0 Type 00000007 Flags 00000050
Vpb 8b52f080 Dacl e13e397c DevExt 8b1b80e8 DevObjExt 8b1b8548 Dope 8b467828
ExtensionFlags (0000000000) 
AttachedDevice (Upper) 8b0556d8 \Driver\PartMgr
AttachedTo (Lower) 8b192030 \Driver\DriverA
Device queue is not busy.

0: kd> !devstack 8b1b8030
  !DevObj   !DrvObj            !DevExt   ObjectName
  8b0556d8  \Driver\PartMgr    8b055790 
> 8b1b8030  \Driver\Disk       8b1b80e8  DR0
  8b192030  \Driver\DriverA    8b1920e8  DriverA1Port1Path0Target0Lun0
!DevNode 8b56f5d0 :
  DeviceInst is “SCSI\Disk&Ven_A&Prod_Virtual_disk&Rev_1.0\4&1588251b&0&000″
  ServiceName is “disk” 

Additionally we look at raw stack data of running threads 8089d8c0 and f7732090. We find the same hardware activity there and plus some network driver activity too. We also see “double fault” symbols:

[...]
8089a554 ffdffec0
8089a558 80a6157e hal!HalEndSystemInterrupt+0x6e
8089a55c ffdffec0
8089a560 8089a570 nt!KiDoubleFaultStack+0×2cc0
8089a564 80a5e902 hal!HalpIpiHandler+0xd2
8089a568 00000002
8089a56c 000000e1
8089a570 8089a600 nt!KiDoubleFaultStack+0×2d50
8089a574 f7549ca2 intelppm!AcpiC1Idle+0×12
8089a578 badb0d00
8089a57c 0002b74b
8089a580 00000000
8089a584 f7298da0 DriverA!DevScsiTimer
8089a588 00000000
8089a58c 00000000
8089a590 0005d373
8089a594 00000000
8089a598 8b4ecaf8
8089a59c 00000000
8089a5a0 8a4b1e20
8089a5a4 00000000
8089a5a8 8089a600 nt!KiDoubleFaultStack+0×2d50
8089a5ac 0002b74b
8089a5b0 ffdffee0
[…]

But they seem to be coincidental:

0: kd> ub 8089a570
^ Unable to find valid previous instruction for 'ub 8089a570'

0: kd> u 8089a570
nt!KiDoubleFaultStack+0x2cc0:
8089a570 00a68980a29c add byte ptr [esi-635D7F77h],ah
8089a576 54 push esp
8089a577 f7000ddbba4b test dword ptr [eax],4BBADB0Dh
8089a57d b702 mov bh,2
8089a57f 0000 add byte ptr [eax],al
8089a581 0000 add byte ptr [eax],al
8089a583 00a08d29f700 add byte ptr [eax+0F7298Dh],ah
8089a589 0000 add byte ptr [eax],al

0: kd> ub 8089a600
                 ^ Unable to find valid previous instruction for 'ub 8089a600'

0: kd> u 8089a600
nt!KiDoubleFaultStack+0x2d50:
8089a600 0100            add     dword ptr [eax],eax
8089a602 0000            add     byte ptr [eax],al
8089a604 ebde            jmp     nt!KiDoubleFaultStack+0x2d34 (8089a5e4)
8089a606 888000000000    mov     byte ptr [eax],al
8089a60c 0e              push    cs
8089a60d 0000            add     byte ptr [eax],al
8089a60f 0000            add     byte ptr [eax],al
8089a611 0000            add     byte ptr [eax],al 

We find the system virtualized:

0: kd> !sysinfo machineid
[...]
SystemManufacturer = Virtualization Vendor A
[...]

Looking at DriverA timestamp we notice it is much older than expected and Google search points to similar cases (but not for virtualized systems) where it was recommended to update that driver.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

This entry was posted on Monday, June 7th, 2010 at 11:41 pm and is filed under Complete Memory Dump Analysis, Crash Dump Analysis, Crash Dump Patterns. You can follow any responses to this entry through the RSS 2.0 feed. You can leave a response, or trackback from your own site.