• Ntdebugging Blog

    Debugging a Crash, Found a Trojan

    • 8 Comments

    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                                    *

    *                                                                             *

    *******************************************************************************

    IRQL_NOT_LESS_OR_EQUAL (a)

    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.

    Arguments:

    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

        2102 characteristics

                Executable

                32 bit word machine

                DLL

     

    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

        DF1F checksum

    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

       .text name

        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

    60000020 flags

             Code

             (no align specified)

             Execute Read

     

    SECTION HEADER #2

      .rdata name

        13AC virtual size

        C000 virtual address

        1400 size of raw data

        A800 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

    40000040 flags

             Initialized Data

             (no align specified)

             Read Only

     

    SECTION HEADER #3

       .data name

         4B0 virtual size

        E000 virtual address

         200 size of raw data

        BC00 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

    C0000040 flags

             Initialized Data

             (no align specified)

             Read Write

     

    SECTION HEADER #4

      .reloc name

         576 virtual size

        F000 virtual address

         600 size of raw data

        BE00 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

    42000040 flags

             Initialized Data

             Discardable

             (no align specified)

             Read Only


    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

    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....$.......

    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................................

       
    image001

     

    image003


    Before any further trouble shooting we asked the customer to clean the Trojan. Once we did that bug checks disappeared.


    Hope you enjoyed reading this post.
  • Ntdebugging Blog

    Hotfix to Enable Mini-Filter Performance Diagnostics With XPerf for Windows Server 2008R2

    • 1 Comments

    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.

     image001 

     

    The Mini-Filter Delays are in the Storage display. So click on the triangle on the left side of Storage and you will see:

    image002 

     

    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.

    Image3

     

    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).

    Image4

     

    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:

    [1/2]    100.0%

    [2/2]    100.0%

    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.

Page 1 of 1 (2 items)