Hi, I'm Manish from Global Escalation Services. I would like to present a multiple random bug check issue, which was caused by malicious code (trojan) running on the machine. This is the walkthrough of how we found the virus on the server.
In this particular dump, the machine crashed with Bugcheck 0xA (IRQL_NOT_LESS_OR_EQUAL) because we got a Page Fault at dispatch level, also known as DPC Level (IRQL 2). Windows system architecture governs that we cannot have a page fault at dispatch level because paging requires I/O, I/O requires a wait, and we cannot wait while the IRQL is above dispatch level. So when this anomaly happens Windows will intentionally crash the machine. We trapped in CcMapData because we touched the address c226d800 which was not valid because it’s paged out. If we look at implementation of CcMapData on MSDN http://msdn.microsoft.com/en-us/library/windows/hardware/ff539155(v=vs.85).aspx we see that this function can only be called below Dispatch Level, but the current CPU IRQL is 2.
So how did this happen? The most likely possibility is that some driver on the stack raised the IRQL by calling KeRaiseIrql and then forgot to lower it by calling KeLowerIrql. There are many drivers on this stack and anyone could be the culprit. It is difficult to track when one of these may have done it as it’s long gone.
We could have enabled IRQL Checking using Driver Verifier to find the culprit but we have to enable it on all drivers listed in the stack (and possibly others), which could cause some performance issues. Also this was not the only crash we were seeing; there were various stop codes. So before going the verifier route I decided to dig more into this dump. I noticed there is an address on the stack for which the module name is not getting resolved. This looked odd (suspicious) as most of the time the debugger does a great job of finding the module. I started investigating what is this module. It turned out to be a Trojan “TrojanDropper:Win32/Sirefef.B”. http://www.microsoft.com/security/portal/Threat/Encyclopedia/Entry.aspx?Name=TrojanDropper%3AWin32%2FSirefef.B
0: kd> !analyze -v
* Bugcheck Analysis *
An attempt was made to access a pageable (or completely invalid) address at an
interrupt request level (IRQL) that is too high. This is usually
caused by drivers using improper addresses.
If a kernel debugger is available get the stack backtrace.
Arg1: c226d800, memory referenced
Arg2: d0000002, IRQL
Arg3: 00000000, bitfield :
bit 0 : value 0 = read operation, 1 = write operation
bit 3 : value 0 = not an execute operation, 1 = execute operation (only on chips which support this level of status)
Arg4: 808b64a6, address which referenced memory
0: kd> kv
ChildEBP RetAddr Args to Child
f78ae41c 808b64a6 badb0d00 00000000 00000001 nt!KiTrap0E+0x2a7 (FPO: [0,0] TrapFrame @ f78ae41c)
f78ae4cc f71a6f2d 8b22d520 f78ae4fc 00000400 nt!CcMapData+0x8c (FPO: [Non-Fpo])
f78ae4ec f71a4494 f78ae7ec 8b64c150 01c6d800 Ntfs!NtfsMapStream+0x4b (FPO: [Non-Fpo])
f78ae560 f71a6df0 f78ae7ec 8b3a7100 e7c50ce0 Ntfs!NtfsReadMftRecord+0x86 (FPO: [Non-Fpo])
f78ae598 f71a6fac f78ae7ec 8b3a7100 e7c50ce0 Ntfs!NtfsReadFileRecord+0x7a (FPO: [Non-Fpo])
f78ae5d0 f718e46d f78ae7ec e7c50cd8 e7c50ce0 Ntfs!NtfsLookupInFileRecord+0x37 (FPO: [Non-Fpo])
f78ae67c f718e541 f78ae7ec e7c50cd8 f718e2cb Ntfs!NtfsWalkUpTree+0xbe (FPO: [Non-Fpo])
f78ae6d8 f718e263 f78ae7ec e7c50cd8 00000000 Ntfs!NtfsBuildNormalizedName+0x44 (FPO: [Non-Fpo])
f78ae704 f7196c2e f78ae7ec 8801d600 e7c50da0 Ntfs!NtfsQueryNameInfo+0x4b (FPO: [Non-Fpo])
f78ae774 f71a0ff6 f78ae7ec 88081cb0 8b5f9260 Ntfs!NtfsCommonQueryInformation+0x291 (FPO: [Non-Fpo])
f78ae7d8 f71a102f f78ae7ec 88081cb0 00000001 Ntfs!NtfsFsdDispatchSwitch+0x12a (FPO: [Non-Fpo])
f78ae8f4 8081df85 8b3a7020 88081cb0 88081cb0 Ntfs!NtfsFsdDispatchWait+0x1c (FPO: [Non-Fpo])
f78ae908 f721fd28 8b2fd220 8b60d308 8b54b020 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])
f78ae934 8081df85 8b5f9260 88081cb0 88081cb0 fltMgr!FltpDispatch+0x152 (FPO: [Non-Fpo])
f78ae948 f721fd28 88081ed0 8b60d308 c000000d nt!IofCallDriver+0x45 (FPO: [Non-Fpo])
f78ae974 8081df85 8b54b020 88081cb0 88081cb0 fltMgr!FltpDispatch+0x152 (FPO: [Non-Fpo])
f78ae988 f5c62bec 88081cb0 8b54a980 88081cb0 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])
WARNING: Stack unwind information not available. Following frames may be wrong.
f78ae99c f5c5e3ee 8b03b690 00000000 f78ae9c0 CtxSbx+0x5bec
f78ae9ac 8081df85 8b03b690 88081cb0 8b0528e0 CtxSbx+0x13ee
f78ae9c0 f61074e1 8b0528e0 8801d600 f78aea00nt!IofCallDriver+0x45 (FPO: [Non-Fpo])
f78ae9e4 f61075d0 8b0a9b80 00081cb0 f78aea08 CtxAltStr+0x44e1
f78ae9f4 8081df85 8b0a9b80 88081cb0 88081ed0 CtxAltStr+0x45d0
f78aea08 8b5cfc89 00000000 87ef0000 87ef9002 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])
f78aec90 8081df85 8b5ef610 8b08c110 8b08c2a8 0x8b5cfc89 <------------ This looks odd what is this module?
f78aeca4 f7241607 8b08c2a8 00000000 f78aece8nt!IofCallDriver+0x45 (FPO: [Non-Fpo])
f78aecb4 f72412b2 8b08c2a8 8b392b70 87f11974 CLASSPNP!SubmitTransferPacket+0xbb (FPO: [Non-Fpo])
f78aece8 f7241533 00000000 00000e00 87f11808 CLASSPNP!ServiceTransferRequest+0x1e4 (FPO: [Non-Fpo])
f78aed0c 8081df85 8b392ab8 00000000 8b2a2670 CLASSPNP!ClassReadWrite+0x159 (FPO: [Non-Fpo])
f78aed20 f74c80cf 8b2b7d80 87f11998 f78aed44 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])
f78aed30 8081df85 8b6e4020 87f11808 87f119bc PartMgr!PmReadWrite+0x95 (FPO: [Non-Fpo])
f78aed44 f7317053 87f119d8 8b6e8148 882b9888 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])
f78aed60 8081df85 8b2b7cc8 87f11808 87f119fc ftdisk!FtDiskReadWrite+0x1a9 (FPO: [Non-Fpo])
f78aed74 f72cf4f5 885360cc 88536098 87f26810 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])
f78aed90 f72d1517 87f11808 885360cc 8b60c470 volsnap!VspDecrementIrpRefCount+0x14f (FPO: [Non-Fpo])
f78aeda8 f72c0398 87f26810 87f26810 88536098 volsnap!VspWriteVolumePhase22+0x3d (FPO: [Non-Fpo])
f78aee30 f72d15d3 00f26810 885360cc 00000000 volsnap!VspAcquireNonPagedResource+0xc6 (FPO: [Non-Fpo])
f78aee50 8081e123 00000000 87f215e8 88536098 volsnap!VspWriteVolumePhase2+0x59 (FPO: [Non-Fpo])
f78aee80 f7241829 f78aeeb0 f72413ec 8b392ab8 nt!IopfCompleteRequest+0xcd (FPO: [Non-Fpo])
f78aee88 f72413ec 8b392ab8 87f215e8 00000001 CLASSPNP!ClassCompleteRequest+0x11 (FPO: [Non-Fpo])
f78aeeb0 8081e123 00000000 8b08c428 8b08c5c0 CLASSPNP!TransferPktComplete+0x1fd (FPO: [Non-Fpo])
f78aeee0 f7266545 8b6e30e8 8b08c428 f78aef24 nt!IopfCompleteRequest+0xcd (FPO: [Non-Fpo])
f78aeef0 f7265a8a 87f856a8 00000001 00000000 SCSIPORT!SpCompleteRequest+0x5e (FPO: [Non-Fpo])
f78aef24 f7265130 8b6e30e8 87f856a8 f78aef9b SCSIPORT!SpProcessCompletedRequest+0x6a7 (FPO: [Non-Fpo])
f78aef9c 8083211c 8b6e30a4 8b6e3030 00000000 SCSIPORT!ScsiPortCompletionDpc+0x2bd (FPO: [Non-Fpo])
f78aeff4 8088dba7 f3f4f92c 00000000 00000000 nt!KiRetireDpcList+0xca (FPO: [Non-Fpo])
f3f4f948 80a603d9 ffdffa02 f3f4f980 f3f4f980 nt!KiDispatchInterrupt+0x37 (FPO: [Uses EBP] [0,0,1])
f3f4f964 80a60577 8b6c226c f3f4f980 8088d91d hal!HalpCheckForSoftwareInterrupt+0x81 (FPO: [Non-Fpo])
f3f4f970 8088d91d 8b304c00 000001a3 f3f4fa04 hal!HalEndSystemInterrupt+0x67 (FPO: [Non-Fpo])
f3f4f970 809395e7 8b304c00 000001a3 f3f4fa04 nt!KiInterruptDispatch+0x5d (FPO: [0,2] TrapFrame @ f3f4f980)
f3f4fa04 80939c37 88139178 88028301 00000008 nt!ObpAllocateObject+0x199 (FPO: [Non-Fpo])
f3f4fa38 808f8d28 00000000 8b76aad0 f3f4fa70 nt!ObCreateObject+0x129 (FPO: [Non-Fpo])
f3f4fb44 80937a40 8b6afd10 00000000 88028398 nt!IopParseDevice+0x710 (FPO: [Non-Fpo])
f3f4fbc4 80933b74 00000000 f3f4fc04 00000042 nt!ObpLookupObjectName+0x5b0 (FPO: [Non-Fpo])
f3f4fc18 808eaee7 00000000 00000000 dffa7c01 nt!ObOpenObjectByName+0xea (FPO: [Non-Fpo])
f3f4fc94 808ec181 077ef198 c0140000 077ef14c nt!IopCreateFile+0x447 (FPO: [Non-Fpo])
f3f4fcf0 808eec10 077ef198 c0140000 077ef14c nt!IoCreateFile+0xa3 (FPO: [Non-Fpo])
f3f4fd30 808897ec 077ef198 c0140000 077ef14c nt!NtCreateFile+0x30 (FPO: [Non-Fpo])
f3f4fd30 7c82847c 077ef198 c0140000 077ef14c nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ f3f4fd64)
077ef22c 00000000 00000000 00000000 00000000 0x7c82847c
The current CPU IRQL is 2, at which pagefaults cannot be serviced, hence windows crashed the machine.
0: kd> !irql
Debugger saved IRQL for processor 0x0 -- 2 (DISPATCH_LEVEL)
Un-assembling from the return address of this unknown driver, to try to confirm that this is really driver code and that it really does belong in this call stack:
0: kd> ub 8b5cfc89
8b5cfc62 8bd7 mov edx,edi
8b5cfc64 c60605 mov byte ptr [esi],5
8b5cfc67 895e18 mov dword ptr [esi+18h],ebx
8b5cfc6a c7460400020000 mov dword ptr [esi+4],200h
8b5cfc71 c7460809000000 mov dword ptr [esi+8],9
8b5cfc78 c7461c70fb5c8b mov dword ptr [esi+1Ch],8B5CFB70h
8b5cfc7f c64603e0 mov byte ptr [esi+3],0E0h
8b5cfc83 ff158c805d8b call dword ptr ds:[8B5D808Ch]
Sure does call IofCallDriver
0: kd> dps 8B5D808Ch l1
8b5d808c 8081df40 nt!IofCallDriver
So what is this driver? In Windows every image starts with a PE header which starts with letters “MZ”. So I started looking for PE header. I took the offset of the module on the stack and went back to its page boundary, then I started moving 1 page back at a time looking for the PE header.
0: kd> dc 8b5cf000
8b5cf000 0010b9f2 f02b0000 3b063c8b 83137538 ......+..<.;8u..
8b5cf010 c08304e9 04f98304 b85fee73 00000001 ........s._.....
8b5cf020 9cb8c35e b98b5d86 00000010 ff8bd02b ^....]......+...
8b5cf030 3b02348b 83137530 c08304e9 04f98304 .4.;0u..........
8b5cf040 b85fee73 00000001 335fc35e ccc35ec0 s._.....^._3.^..
8b5cf050 83ec8b55 78a04cec 538b5da4 c0b60f56 U....L.x.].SV...
8b5cf060 827ae857 ff330000 33f46589 f845c7db W.z...3..e.3..E.
8b5cf070 00000400 8b084d8b 52510c55 50b4458d .....M..U.QR.E.P
0: kd> dc 8b5cf000-1000
8b5ce000 01c73024 00000000 c70cc483 00800002 $0..............
8b5ce010 845e5f00 b10874db 0815ff01 8b8b5d80 ._^..t.......]..
8b5ce020 6a0c2444 15ff5000 8b5d8028 14c25b5d D$.j.P..(.].][..
8b5ce030 cccccc00 cccccccc cccccccc cccccccc ................
8b5ce040 6a306a56 2415ff00 8b8b5d80 74f685f0 Vj0j...$.].....t
8b5ce050 6a006a53 68026a01 8b5d0892 5d08ae68 Sj.j.j.h..].h..]
8b5ce060 ff006a8b 5d80ac15 ff56508b 5d80a815 .j.....].PV....]
8b5ce070 000d8b8b ff8b5da2 5d80b015 6a006a8b .....].....].j.j
0: kd> dc 8b5cf000-1000*2
8b5cd000 0689c033 89044689 46890846 1046890c 3....F..F..F..F.
8b5cd010 89144689 ec831846 1c46891c 57204689 .F..F.....F..F W
8b5cd020 85244689 8d0574f6 02eb284e c033c933 .F$..t..N(..3.3.
8b5cd030 41890189 08418904 8b34468b 4e891048 ...A..A..F4.H..N
8b5cd040 14508b10 8b145689 4e891848 1c508b18 ..P..V..H..N..P.
8b5cd050 8b1c5689 4e891848 1c508b20 2424448d .V..H..N .P..D$$
8b5cd060 244c8d50 186a510c 8b245689 6a302454 P.L$.Qj..V$.T$0j
8b5cd070 46c65205 46c70005 00000008 0c46c700 .R.F...F......F.
Finally I found the PE header for this image.
0: kd> dc 8b5cf000-1000*3
8b5cc000 00905a4d 00000003 00000004 0000ffff MZ..............
8b5cc010 000000b8 00000000 00000040 00000000 ........@.......
8b5cc020 00000000 00000000 00000000 00000000 ................
8b5cc030 00000000 00000000 00000000 000000d0 ................
8b5cc040 0eba1f0e cd09b400 4c01b821 685421cd ........!..L.!Th
8b5cc050 70207369 72676f72 63206d61 6f6e6e61 is program canno
8b5cc060 65622074 6e757220 206e6920 20534f44 t be run in DOS
8b5cc070 65646f6d 0a0d0d2e 00000024 00000000 mode....$.......
Using the built-in debugger extension !dh I dumped the header of this image to find the name. Unfortunately there is no name for this image. This address 8b5cc000 is not in the loaded module list, which raised further suspicion. Either it is hiding its load address or this driver was not loaded by standard loading mechanism. This module date shows it’s pretty recent build.
0: kd> !dh 8b5cc000
File Type: DLL
FILE HEADER VALUES
14C machine (i386)
4 number of sections
4EA3461E time date stamp Sun Oct 23 04:09:26 2011
0 file pointer to symbol table
0 number of symbols
E0 size of optional header
32 bit word machine
OPTIONAL HEADER VALUES
10B magic #
9.00 linker version
A400 size of code
2000 size of initialized data
0 size of uninitialized data
46C0 address of entry point
1000 base of code
----- new -----
10000000 image base
1000 section alignment
200 file alignment
1 subsystem (Native)
5.00 operating system version
0.00 image version
5.00 subsystem version
10000 size of image
400 size of headers
00100000 size of stack reserve
00001000 size of stack commit
00100000 size of heap reserve
00001000 size of heap commit
0 DLL characteristics
0 [ 0] address [size] of Export Directory
C91C [ 3C] address [size] of Import Directory
0 [ 0] address [size] of Resource Directory
0 [ 0] address [size] of Exception Directory
0 [ 0] address [size] of Security Directory
F000 [ 3FC] address [size] of Base Relocation Directory
0 [ 0] address [size] of Debug Directory
0 [ 0] address [size] of Description Directory
0 [ 0] address [size] of Special Directory
0 [ 0] address [size] of Thread Storage Directory
0 [ 0] address [size] of Load Configuration Directory
0 [ 0] address [size] of Bound Import Directory
C000 [ 1A8] address [size] of Import Address Table Directory
0 [ 0] address [size] of Delay Import Directory
0 [ 0] address [size] of COR20 Header Directory
0 [ 0] address [size] of Reserved Directory
SECTION HEADER #1
A354 virtual size
1000 virtual address
A400 size of raw data
400 file pointer to raw data
0 file pointer to relocation table
0 file pointer to line numbers
0 number of relocations
0 number of line numbers
(no align specified)
SECTION HEADER #2
13AC virtual size
C000 virtual address
1400 size of raw data
A800 file pointer to raw data
SECTION HEADER #3
4B0 virtual size
E000 virtual address
200 size of raw data
BC00 file pointer to raw data
SECTION HEADER #4
576 virtual size
F000 virtual address
600 size of raw data
BE00 file pointer to raw data
0: kd> !lmi 8b5cc000
Loaded Module Info: [8b5cc000]
ffffffff8b5cc000 is not a valid address
0: kd> lmvm 8b5cc000
start end module name
Checking the import table it does have calls to raise and lower the IRQL. We get to the import table by taking the base address plus the offset to the Import Address Table Directory. The below output is just a snippet of the whole table.
0: kd> dps 8b5cc000+c000
8b5d8000 80a603f4 hal!KfLowerIrql
8b5d8004 80a5ff00 hal!KeGetCurrentIrql
8b5d8008 80a600b4 hal!KfRaiseIrql
Dumping the entire image contents in memory to find more clues about this driver. Again, I am only showing snippets of the whole output.
0: kd> dc 8b5cc000 L?10000/4
8b5cc070 65646f6d 0a0d0d2e 00000024 00000000 mode....$.......
8b5d5e20 76000000 66697265 77252079 00000a5a ...verify %wZ...
8b5d5e30 31000000 35343332 39383736 33323130 ...1234567890123
8b5d5e40 37363534 31303938 35343332 39383736 4567890123456789
8b5d5e50 33323130 37363534 31303938 35343332 0123456789012345
8b5d5e60 39383736 33323130 37363534 31303938 6789012345678901
8b5d5e70 00343332 66000000 646e756f 67697320 234....found sig
8b5d5e80 7574616e 3d206572 0a752520 b4000000 nature = %u.....
Interestingly this image has other images (modules) embedded in it. We can see other PE headers, which again have no name. This looks highly suspicious and resembles behavior used by malicious software.
8b5d0970 f775c085 4848c78b 4dc35f5e 0300905a ..u...HH^_.MZ...
8b5d0980 04000000 ff000000 b80000ff 00000000 ................
8b5d0990 40000000 00000000 00000000 00000000 ...@............
8b5d09a0 00000000 00000000 00000000 00000000 ................
8b5d09b0 00000000 c8000000 0e000000 000eba1f ................
8b5d09c0 21cd09b4 cd4c01b8 69685421 72702073 ...!..L.!This pr
8b5d09d0 6172676f 6163206d 746f6e6e 20656220 ogram cannot be
8b5d09e0 206e7572 44206e69 6d20534f 2e65646f run in DOS mode. 8b5d2200 4d00004e 0300905a 04000000 ff000000 N..MZ...........
8b5d2210 b80000ff 00000000 40000000 00000000 ...........@....
8b5d2220 00000000 00000000 00000000 00000000 ................
8b5d2230 00000000 00000000 00000000 f0000000 ................
8b5d2240 0e000000 000eba1f 21cd09b4 cd4c01b8 ...........!..L.
8b5d2250 69685421 72702073 6172676f 6163206d !This program ca
8b5d2260 746f6e6e 20656220 206e7572 44206e69 nnot be run in D
8b5d2270 6d20534f 2e65646f 240a0d0d 00000000 OS mode....$....
After ensuring my AV definitions were up to date, I decided to dump this memory contents into a file onto my machine. The moment contents were written my AV Microsoft Forefront Endpoint Protection caught a Trojan in this file.
0: kd> .writemem c:\temp\drv.sys 8b5cc000 L?10000 Writing 10000 bytes................................
Greetings ntdebugging community, Bob here again and today I would like to let everyone know about a new feature implemented in Windows Server 2008 R2’s kernel and filter manager binaries released in knowledge base article 2666390.
Beginning with this update, a minifilter that is adversely affecting system performance can be identified in Windows 2008 R2. These measurements are taken within the filter manager and measure the execution time of the minifilter’s pre and post operations. On every file access file system minifilters are given the chance to perform pre and post modifications to IO operations within the driver stack.
To start recording the operations and to view the results, the latest version of the Windows Performance Toolkit from the Windows 8 beta ADK needs to be installed on the system. How to install the package can be found in the KB article.
The command to start recording and to record stack traces is (note that these commands may wrap depending on your screen resolution, they are intended to be typed in one line):
xperf -on PROC_THREAD+LOADER+FLT_IO_INIT+FLT_IO+FLT_FASTIO+FLT_IO_FAILURE+FILENAME -stackwalk MiniFilterPreOpInit+MiniFilterPostOpInit
The command above starts a trace with most of the buffering done in memory. The command below specifies a file used as a backing store to use less memory:
xperf -start -f <traceFile> -on PROC_THREAD+LOADER+FLT_IO_INIT+FLT_IO+FLT_FASTIO+FLT_IO_FAILURE+FILENAME -stackwalk MiniFilterPreOpInit+MiniFilterPostOpInit
Note: <traceFile> is the path of the file to store the backing file (i.e. trace.etl). It is recommended that the backing file be placed on a drive other than the one experiencing the problem, to avoid xperf operations interfering with or contributing to the scenario you are measuring. You can add the +FILENAME switch if you want to log names of the files that the minifilter is operating on.
You may not know if a minifilter is causing the problem until after you begin data analysis, so you can add the filter manager tracing to the Driver Delays command presented in my previous blog, Using Xperf to investigate slow I/O issues.
xperf -on PROC_THREAD+LOADER+CSWITCH+FILENAME+FILE_IO+FILE_IO_INIT+DRIVERS+FLT_IO_INIT+FLT_IO+FLT_FASTIO+FLT_IO_FAILURE -f kernel.etl -stackwalk CSwitch+DiskReadInit+DiskWriteInit+DiskFlushInit+FileCreate+FileCleanup+FileClose+FileRead+FileWrite+MiniFilterPreOpInit+MiniFilterPostOpInit -BufferSize 1024 -MaxBuffers 1024 -MaxFile 1024 -FileMode Circular
To stop the trace and flush data to the trace file, type the following command:
xperf –stop –d mymergedtrace.etl
The file specified must be a different file name than the one provided with the –f switch if that option was used when starting the trace.
Before we begin looking at the trace, let’s talk a little about what we are tracing. We are tracing fltmgr calling into the minifilter. The fltmgr manages minifilters. When a file operation is done, each minifilter has a chance to process and optionally modify an operation on a file before and after the call goes into the file system. For example, in this case we are going to see results of the time it took for the minifilter to do a “pre create” operation. That is the function that is called before the “create file” function is sent to the file system. This tracing can also track the time it took for the minifilter to do a “post create” operation. That is the minifilter function that gets called after the create file is sent to the file system. So the minifilter is called before and after every file system operation. The minifilter may not have functions to process before and after, however it has the option.
Once the problem is traced, the data can be viewed by clicking on the merged etl file and you will see a similar presentation as below.
The Mini-Filter Delays are in the Storage display. So click on the triangle on the left side of Storage and you will see:
To get more detail, right click on the “Mini-Filter Delays” section and select “Add To New Analysis View”and that will bring up minifilter delays detail as below.
The Duration is the time in micro seconds of the total time delay in the minifilter. So in the example above the scanner minifilter did 4,068 requests and it took 30 seconds total.
We can expand the display by clicking on the triangle next to scanner.sys to get a more detailed view, I chose to investigate scanner.sys because it has the longest Duration. I dragged the “Major Function Name (Count)” and “File Name” columns to the left of the yellow bar to get detail and used the triangles to expand the ProcessID with the longest Duration, and then I expanded the File Name with the longest Duration. To get more usable space on your monitor, you can click the X to close the Graph Explorer (to get it back, from the Window menu choose Graph Explorer).
On the display above it shows the scanner.sys filter was operating on the file “C:\users\Administrator\Desktop\scanner\test2.txt” The green 6 is the total operations. So there were three cleanups and three creates. So the display is telling us that the filter did 3 “create” operations that took close to 15 seconds and 3 cleanup operations that took 5 milliseconds on the file.
If you prefer operating from a command line rather than a GUI, this same data can be extracted using the below command. Note that -min specifies the time in ns, so this command will show delays longer than 100 ms.
xperf -i mymergedtrace.etl -a minifilterdelay -min 100000
This will give you output similar to the below information:
There are 3 MiniFilter Delay completion events in given time range.
Process Name, Module Name, Call (us), Return (us), Time (us), Major Func Name, Filename
explorer.exe, scanner.sys, 18649145, 23645502, 4996357, CREATE, C:\Users\Administrator\Desktop\scanner\test2.txt
explorer.exe, scanner.sys, 23646355, 28644638, 4998282, CREATE, C:\Users\Administrator\Desktop\scanner\test2.txt
explorer.exe, scanner.sys, 28645194, 33645158, 4999964, CREATE, C:\Users\Administrator\Desktop\scanner\test2.txt
It seems there is a problem in the create file handling of the scanner.sys minifilter. For some reason the create file function in the minifiltertook 5 seconds for each operation. The vendor of this filter would need to do additional investigation to identify why the filter has this delay.