IRP distribution anomaly, inconsistent dump, execution residue, hardware activity, coincidental symbolic information, not my version, virtualized system: pattern cooperation
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 -
June 8th, 2010 at 11:37 pm
[…] Comments 0 http://www.dumpanalysis.org/blog/index.php/2010/06/07/irp-distribution-anomaly-inconsistent-dump-exe… […]
August 10th, 2010 at 5:00 pm
[…] http://www.dumpanalysis.org/blog/index.php/2010/06/07/irp-distribution-anomaly-inconsistent-dump-exe… […]