• Ntdebugging Blog

    I Want A Debugger Robot

    • 1 Comments

    Hi,

     

    My name is Sabin from the Platforms Global Escalation Services team at Microsoft, and today I want to share with you a recent experience I had debugging an issue reported by an hardware manufacturer.

     

    The customer was doing a reboot test for their new server product line. They found that after hundreds of continuous reboots there was always a single instance that the server took more than 20 minutes to start up, when compared to an average 2 minute normal startup time. This happened only once every 300+ to 1000+ reboots. The number of reboots it took before the problem happened again varied randomly so it was difficult to predict when the problem would occur.

     

    Although they setup a live kernel debugging environment, they didn’t want to watch the computer screen for 10+ hours waiting for the problem to happen so they could manually hit Ctrl+Break in windbg. So instead they setup a video camera to film the computer screen 24x7, and they managed to find that when the “mysterious delay” happened the computer showed a gray screen with “Microsoft (R) Windows (R) version 5.1 (Build 3790: Service Pack 2)”.

     

    The case came to me and the customer even shipped a problematic server to our office to troubleshoot the cause of the delay. The problem was that I didn’t want to stare at the computer screen for 10+ hours either!

     

    The first thing I thought was that it would be fantastic if there were a robot sitting in front of Windbg, watching the elapsed time for each reboot, so it could hit Ctrl+Break in windbg if the server takes more than 10 minute to start. Then I asked myself, “Why not?”

     

    I decided to build such a “robot” myself.  I went around and checked the Debuggers SDK document (which can be found in the windbg help document debugger.chm), and I realized that what I needed was a customized debugger. The functionality of the debugger is simple, it should be able to recognize the time when the server first starts and the time when the server reboots. If there is more than 10 minutes between these two times the customized debugger automatically breaks in to the server. The event callback interface IDebugEventCallbacks::SessionStatus and the client interface IDebugControl::SetInterrupt can meet my needs perfectly.

     

    It is not that difficult to build such a customized debugger, which I called DBGRobot. I would like to share some code snippets which you may find helpful when building a customized debugger for a special debugging scenario, or as the basis for building a more complicated debugging robot.

     

    First, we need to download and install the Windows Driver Kit Version 7.1.0. When installing the WDK be sure to select Debugging Tools for Windows.

     

     

     

    If you install the WDK to its default folder, which for version 7.1.0 is C:\WinDDK\7600.16385.1, the C:\WinDDK\7600.16385.1\Debuggers\sdk\samples folder will contain the sample code from the Debugger SDK. The dumpstk sample is the one particularly interesting to us. We can copy some common code from it, such as the out.cpp and out.hpp which is the implementation of the IDebugOutputCallbacks interface.

     

    Now let’s do some coding.  The common code is copied from the Debuggers SDK sample Dumpstk. I also listed it here for clarity.

     

    The first step is to create the IDebugClient, IDebugControl and IDebugSymbols interfaces (although IDebugSymbols is not used in this case). You need to call the DebugCreate() function to create the IDebugClient interface, and then use IDebugClient->QueryInterface() to query the IDebugControl and IDebugSymbols interfaces.

     

    void

    CreateInterfaces(void)

    {

        HRESULT Status;

     

        // Start things off by getting an initial interface from

        // the engine.  This can be any engine interface but is

        // generally IDebugClient as the client interface is

        // where sessions are started.

        if ((Status = DebugCreate(__uuidof(IDebugClient),

                                  (void**)&g_Client)) != S_OK)

        {

            Exit(1, "DebugCreate failed, 0x%X\n", Status);

        }

     

        // Query for some other interfaces that we'll need.

        if ((Status = g_Client->QueryInterface(__uuidof(IDebugControl),

                                               (void**)&g_Control)) != S_OK ||

            (Status = g_Client->QueryInterface(__uuidof(IDebugSymbols),

                                               (void**)&g_Symbols)) != S_OK)

        {

            Exit(1, "QueryInterface failed, 0x%X\n", Status);

        }

    }

     

    If you want to see the output from the debugging engine, you also need to implement the IDebugOutputCallbacks interface. The main function to be implemented is IDebugOutputCallbacks::Output(), which is quite simple as we only need to see the output in the command prompt stdout stream:

     

    STDMETHODIMP

    StdioOutputCallbacks::Output(

        THIS_

        IN ULONG Mask,

        IN PCSTR Text

        )

    {

        UNREFERENCED_PARAMETER(Mask);

        fputs(Text, stdout);

        return S_OK;

    }

     

    Here comes our main code logic: we need to implement the IDebugEventCallbacks interface and monitor the SessionStatus events. In order for the debugger engine to deliver the SessionStatus events to us we need to set the DEBUG_EVENT_SESSION_STATUS mask in IDebugEventCallbacks::GetInterestMask():

     

    STDMETHODIMP_(HRESULT)

    RobotEventCallBacks::GetInterestMask(

            THIS_

            OUT PULONG Mask

            )

    {

     

        // Here we monitor all the event types, although it is not necessary

        *Mask = DEBUG_EVENT_SESSION_STATUS | DEBUG_EVENT_EXCEPTION | DEBUG_EVENT_CHANGE_DEBUGGEE_STATE | DEBUG_EVENT_CHANGE_ENGINE_STATE;    

        return S_OK;

     

    }

     

    In the RobotEventCallBacks::SessionStatus() function, if we receive the DEBUG_SESSION_ACTIVE session status we know that Windows has started and connected to the debug session. Once the OS has started we create a new thread that waits for hEvent, an unnamed global event. In the new thread we send a timeout value for 10 minutes to the WaitForSingleObject() call.  The hEvent will be set when the session status is DEBUG_SESSION_END or DEBUG_SESSION_REBOOT, which means that the server rebooted and disconnected from the debug session. If WaitForSingleObject() returns WAIT_TIMEOUT, indicating that the server has not rebooted after 10 minutes, we send a break to the server via g_Control->SetInterrupt(DEBUG_INTERRUPT_ACTIVE).

     

    STDMETHODIMP_(HRESULT)

    RobotEventCallBacks::SessionStatus(

        THIS_

        IN ULONG Status

        )

    {

                   

        printf("Session Status changed, status = %d \n", Status);

     

        if (Status == DEBUG_SESSION_ACTIVE)

        {

                    //bSessionActive = TRUE;

                    ::CreateThread(NULL, 0, (LPTHREAD_START_ROUTINE)TimerThread, NULL, 0, NULL);

        }

        else if ((Status == DEBUG_SESSION_END) || (Status == DEBUG_SESSION_REBOOT) )

        {

                    //bSessionActive = FALSE;

                    SetEvent(hEvent);

     

        }

     

        return S_OK;

    }

     

    STDMETHODIMP_(HRESULT)

    RobotEventCallBacks::Exception(

          THIS_

          IN PEXCEPTION_RECORD64 Exception,

          IN ULONG FirstChance

          )    

    {

          printf("Captured exception 0x%x, FirstChance = %d", Exception->ExceptionCode, FirstChance);

          if (FirstChance && Exception->ExceptionCode == 0x80000003)

          {

                bInterrupted = TRUE;

          }

         

          return DEBUG_STATUS_NO_CHANGE;

    }

     

    void TimerThread()

    {

                    HRESULT Status;

                    DWORD result;

     

                    result = WaitForSingleObject(hEvent,10*60*1000);

     

                    if (result == WAIT_OBJECT_0) //the close event is signled within 10 minutes

                    {

                                    printf("Target reboots within 10 minutes \n");             

                                   

                    }

                    else if (result == WAIT_TIMEOUT)  //the close event is not singled within 10 minute, it means the server hangs

                    {

                        if ((Status = g_Control->SetInterrupt(DEBUG_INTERRUPT_ACTIVE)) !=S_OK)  //force the target to break

                        {

                                    Exit(1, "SetInterrupt failed, 0x%x\n", Status);

                        }

                                       

                    }

                   

    }

     

    Below is our main function. In the main function we need to create the interfaces, and set the callback interfaces g_Client->SetOutputCallbacks and g_Client->SetEventCallbacks. Then we call g_Control->WaitForEvent() in the while(TRUE) loop, which is a typical main loop for a debugger program. If WaitForEvent() returns it means that a debugging event happened, such an exception, and then you can send some debug commands via g_Control->Execute. Here we simply send a “.time” command to record the problematic time. The bInterrupted boolean is set in the RobotEventCallBacks::Exception() function when it detects a first chance 80000003 exception, which means a debugger break-in.

     

    Note: Initially I wanted to send a “.crash” command to crash the server and generate the memory dump.  When I tried this I found that although the “.crash” command did trigger a blue screen it failed to generate a memory dump because the problem happened so early in the boot process and the paging file was not initialized yet. So I changed it to just send a “.time” command and performed live debugging after the problem was captured by the tool. Initially I had forgotten to change the printf output, which is why you see the output “Succeeded in capturing the problem and crashing the server!” in the below screenshot.

     

    void __cdecl

    main(int argc, char* argv[])

    {

     

        HRESULT Status;

       

        hEvent = CreateEvent(NULL, FALSE, FALSE, NULL);  //create the global hEvent

     

        CreateInterfaces();  //create the global interfaces

     

        if ((Status = g_Client->SetOutputCallbacks(&g_OutputCb)) != S_OK)  //set the output callback interface

        {

            Exit(1, "SetOutputCallbacks failed, 0x%X\n", Status);

        }

     

        if ((Status = g_Client->SetEventCallbacks(&g_EventCb)) != S_OK)  //Set the event callback interface

        {

            Exit(1, "SetEventCallbacks failed, 0x%X\n", Status);

        }

     

     

     

        Status = g_Client->AttachKernel(DEBUG_ATTACH_KERNEL_CONNECTION, argv[1]); //Attach to the kernel debugging, the argv[1] should be “COM:Port=COM1,baud=115200”

     

        if (Status != S_OK)

        {

                    Exit(1, "AttachKernel failed, 0x%X\n", Status);              

     

        }

     

        while(TRUE)  //This is the main loop of the debugger program, it calls g_Control->WaitForEvent() repeatedly waiting for the debugging events

        {

     

                        Status = g_Control->WaitForEvent(DEBUG_WAIT_DEFAULT,

                                                              INFINITE);  //wait for 10 minutes

                                                             

                        printf("WaitForEvent returned. Status = 0x%x\n", Status);

                       

                       

                        if (Status == S_OK && bInterrupted)

                        {

                                    if ((Status = g_Control->Execute(DEBUG_OUTCTL_THIS_CLIENT, ".time", DEBUG_EXECUTE_ECHO)) !=S_OK)  //do .time to record the time the problem happens

                                        {

                                                    Exit(1, "Execute failed, 0x%x\n", Status);

                   

                                        }

                                       

                                    Exit(0, "Succeeded in capturing the problem!");

                        }

        }

       

        Exit(0, NULL);

    }

     

    Now that we have the code we can build DBGRobot.exe using the WDK 7.1.0 build environment. Remember to set the following environment variables, as mentioned in the readme.txt under \WinDDK\7600.16385.1\Debuggers\samples

     

    SET DBGLIB_LIB_PATH=C:\WinDDK\7600.16385.1\Debuggers\sdk\lib

    SET DBGSDK_INC_PATH=C:\WinDDK\7600.16385.1\Debuggers\sdk\inc

    SET DBGSDK_LIB_PATH=C:\WinDDK\7600.16385.1\Debuggers\sdk\lib

     

    Now I have the “robot” watching the problem for me. I set up the live kernel debugging environment as usual and then ran the DBGRobot.exe tool as the debugger instead of windbg.  I used the command: dbgrobot.exe com:port=COM1,baudrate=115200.

     

    This is the screenshot when the server starts and reboots normally:

    image

     

    I let the DBGRobot.exe run over night, and in the morning when I came back to the office, the “robot” had done its job perfectly and captured the problem for me! The problematic server was left in the break-in state so I just needed to launch windbg to attach to the server, and then I could do the debugging in windbg as normal.

    image

     

    The cause of the delay turned out to be a hardware problem, but the actual problem is not important here. I hope this article can give you some new ideas about debugging, and using the debug tools in new ways.

     

  • Ntdebugging Blog

    Part 3: Understanding !PTE - Non-PAE and X64

    • 1 Comments

    Hello, Ryan Mangipano (ryanman) again with part three of my series on understanding the output of the !PTE command. In this last installment I’ll continue our manual conversion of Virtual Addresses by converting a Non-PAE VA. Afterwards I’ll convert a VA from X64 Long Mode. Then I’ll discuss the TLB. If you haven’t read part one and two of this series I recommend taking a looking before jumping into the rest of this article.

    Non-PAE system VA to Physical Address conversion

    In part 1 and part 2 I discussed using windbg to manually x86 PAE virtual to physical address conversion with 4KB and 2MB pages. Now I’ll mention the same thing for Non-PAE systems. The official processor manuals explain how systems not using PAE have only two level of tables instead of the three used by PAE. This fact is because PAE added the Page Directory Pointer Table. This means the CR3 register will contain a pointer to the Page Directory Table. Also note the size of the table entries will be 32-bit, not the 64-bit size observed in the PAE tables. PAE expanded the table size to allow for more bits for the purpose of allowing the addressing of more physical memory.

    The PAE bit is bit number five, which is the sixth bit due to bit numbering starting at zero. You can see PAE is not enabled on this system.

           0: kd> .formats @cr4

      Binary:  00000000 00000000 00000110 11010001

     Another method of checking this:

                   1: kd> j ((@cr4 & 0y00000000000000000000000000100000) != 0) '.echo PAE flag Enabled';'.echo PAE flag Disabled'

    PAE flag Enabled

     Now I'll use the following random virtual address which is valid:

     

    0: kd> !pte f72c5c00

    F72C5C00  - PDE at C0300F70        PTE at C03DCB14

              contains 01014963      contains 06CE7963

            pfn 1014 G-DA--KWV    pfn 6ce7 G-DA—KWV

     

    0: kd> .formats f72c5c00

      Binary:  11110111 00101100 01011100 00000000

     Let’s break it down:

     

    PD offset                        11110111 00

    Page Table Offset                       101100 0101

    Offset in the Physical Page             1100 00000000 (since it’s a even 12 bits,  just refer to it in hex as c00)

     

    0: kd> !dd @cr3 + (0y1111011100 * @@(sizeof(nt!HARDWARE_PTE)))L1

    # a07df70 01014963

     

    0: kd> !dd 1014000 + (0y1011000101 * @@(sizeof(nt!HARDWARE_PTE)))L1

    # 1014b14 06ce7963

     Now that I have the physical page base, I'll place  the last 3 hex digits (c00)  from the Virtual Address onto the address base.

     

    0: kd> !dd 6ce7c00 L4

    # 6ce7c00 00000001 c0000005 00000000 00000000

     

    0: kd> dd f72c5c00 L4

    f72c5c00  00000001 c0000005 00000000 00000000

    X64 VA to Physical Address Conversion

    Just as PAE added a third level to the non-PAE two-level system, x64 Long mode adds a fourth level to the hierarchy.  This table is called the Page-Map Level-4 (PML4 table). AMD refers to the entries in this table as PML4E (Page-Map Level-4 Entry).  Intel refers to each entry as PML4-Table Entry. Internally we refer to this as the eXtended Page directory Entry (PXE).  Regardless of how you refer to these entries they contain indexes into the PDP table (Page Directory Pointer Table).

     Here is the output of the !pte command against a 64-bit address:

                   7: kd> !pte fffffade`c24eb7c0

                                     VA fffffadec24eb7c0

    PXE @ FFFFF6FB7DBEDFA8     PPE at FFFFF6FB7DBF5BD8    PDE at FFFFF6FB7EB7B090    PTE at FFFFF6FD6F612758

    contains 0000000111800863  contains 0000000119826863  contains 0000000119839963  contains 0000000001FF6121

    pfn 111800     ---DA--KWEV  pfn 119826     ---DA--KWEV  pfn 119839     -G-DA--KWEV  pfn 1ff6       -G--A—KREV

    I'll break it down in binary and use data from the processor manuals to separate the bits

     

    7: kd> .formats fffffade`c24eb7c0

      Binary:  11111111 11111111 11111010 11011110 11000010 01001110 10110111 11000000

     

    Sign extend               11111111 11111111

    PML4 offset               11111010 1

    PDP offset                1011110 11

    PD offset                 000010 010

    Page-Table offset         01110 1011

    Physical Page Offset      0111 11000000

     

     Now that I have the numbers, I'll plug them in and find the physical address. If you are having problems following along, refer to part one of this blog and the AMD x64 System Programming manual. You should be comparing the output below to the !pte output above

     

    7: kd> !dq @cr3 + ( 0y111110101 * @@(sizeof(ntkrnlmp!HARDWARE_PTE))) L1

    #  147fa8 00000001`11800863

     

    7: kd> !dq 0x00111800000 + (  0y101111011  * @@(sizeof(ntkrnlmp!HARDWARE_PTE))) L1

    #111800bd8 00000001`19826863

     

    7: kd> !dq 0x119826000 + ( 0y000010010  * @@(sizeof(ntkrnlmp!HARDWARE_PTE))) L1

    #119826090 00000001`19839963

     

    7: kd> !dq 0x119839000 + ( 0y011101011  * @@(sizeof(ntkrnlmp!HARDWARE_PTE))) L1

    #119839758 00000000`01ff6121

     

    7: kd> !dc 1ff67c0 L4

    # 1ff67c0 5085ff48 48000005 68244c8b 04a8f633 H..P...H.L$h3...

     

    7: kd> dc fffffade`c24eb7c0 L4

    fffffade`c24eb7c0  5085ff48 48000005 68244c8b 04a8f633  H..P...H.L$h3...

    TLB- Translation Lookaside Buffer and Conclusion

    The CPU’s memory management unit performs these operations to translate virtual addresses to physical. Wouldn’t it be great if we could cache the virtual address to physical page information in a location that can be accessed very quickly so that the CPU doesn’t have to look this up for future references to this page?  That is just what the Translation Lookaside Buffer (TLB) does. Hopefully this will shed some light on some basic memory structures like Large Pages, Flags, and the TLB so I encourage you to read more about these topics from the following sources-

    How PAE x86 works (on MSDN): http://technet.microsoft.com/en-us/library/cc736309(WS.10).aspx

    Intel  & AMD processor manuals: http://www.intel.com/products/processor/manuals/index.htm and http://developer.amd.com/documentation/guides/Pages/default.aspx#manuals

    “Windows Internals, 5th Edition” Mark E. Russinovich and David A. Solomon with Alex Ionescu  -Chapter 9: Memory Management

     

     

  • Ntdebugging Blog

    ‘Hidden’ ETW Stack Trace Feature – Get Stacks All Over the Place!

    • 0 Comments

     

    I’ve heard Mark R. say that “sometimes Microsoft gave me a gift” when coming across an interesting feature not in mainstream documentation.  How true that often the odd find can prove ultimately very valuable.  Such was the case when I read Bruce Dawson’s Stack Walking in Xperf blog entry.

    Here’s the excerpt that blew me away:

    You can also record call stacks for manifest-based ETW (Event Tracing for Windows) events, but the syntax is quite different, and it only works on Windows 7 and above. When you specify your ETW provider to xperf after “-on” you can specify extra parameters after the provider name, separated by colons. These are flags, a level, and, for manifest-based providers, a list of extra data to record, which can include call stacks. You can leave the flags and level fields blank and just specify ‘stack’ (in single quotes) after three colons like this:

         xperf -on Latency -stackwalk profile -start browse -on Microsoft-IE:::'stack'  
         rem Your scenario goes here...     
         xperf -stop browse -stop -d mytrace.etl

    This sounds rather ordinary at first,  but looking at the syntax you may realize that this means for just about every manifest based provider (Microsoft-*) one can generate a stack trace on all ETW events therein.  This is really cool because if you are only interested in stacks, you don’t have to monkey around with any other trace level or flags which is often the most frustrating part about manual ETW tracing.  Recall from Ivan’s blog that there are over 600+ inbox providers to explore so we can go crazy here exploring components!  Let’s demonstrate.

    First, remember to use the Win7 SDK version of XPerf.  The XPerf(WPT) install *.msi files are found in the Bin directory after installing Win32 Development Tools, so you have to do a two-step at present to get the tools installed.

    Let’s list all the providers…

    C:\utils\xperf7sdk>xperf -providers | findstr "Microsoft-"
          .
           .
           .
           93c05d69-51a3-485e-877f-1806a8731346:0x0001000000000000:0x4       : Microsoft-Windows-LUA
           9580d7dd-0379-4658-9870-d5be7d52d6de:0x0001000000000000:0x4       : Microsoft-Windows-WLAN-AutoConfig
           959f1fac-7ca8-4ed1-89dc-cdfa7e093cb0:0x0001000000000000:0x4       : Microsoft-Windows-HealthCenterCPL
           96ac7637-5950-4a30-b8f7-e07e8e5734c1:0x0001000000000000:0x4       : Microsoft-Windows-Kernel-BootDiagnostics
           96f4a050-7e31-453c-88be-9634f4e02139:0x0001000000000000:0x4       : Microsoft-Windows-UserPnp
           98583af0-fc93-4e71-96d5-9f8da716c6b8:0x0001000000000000:0x4       : Microsoft-Windows-Dwm-Udwm
           a50b09f8-93eb-4396-84c9-dc921259f952:0x0001000000000000:0x4       : Microsoft-Windows-Diagnosis-MSDE<
           ad5162d8-daf0-4a25-88a7-01cbeb33902e:0x0001000000000000:0x4       : Microsoft-Windows-WPDClassInstaller
           ae4bd3be-f36f-45b6-8d21-bdd6fb832853:0x0001000000000000:0x4       : Microsoft-Windows-Audio
           af2e340c-0743-4f5a-b2d3-2f7225d215de:0x0001000000000000:0x4       : Microsoft-Windows-Netshell
           b03d4051-3564-4e93-93db-3c34f1b5b503:0x0001000000000000:0x4       : Microsoft-Windows-Diagnosis-TaskManager
           b1f90b27-4551-49d6-b2bd-dfc6453762a6:0x0001000000000000:0x4       : Microsoft-Windows-PowerCpl
           b2a40f1f-a05a-4dfd-886a-4c4f18c4334c:0x0001000000000000:0x4       : Microsoft-PerfTrack-IEFRAME
           c89b991e-3b48-49b2-80d3-ac000dfc9749:0x0001000000000000:0x4       : Microsoft-Windows-Documents
           c9bdb4eb-9287-4c8e-8378-6896f0d1c5ef:0x0001000000000000:0x4       : Microsoft-Windows-HomeGroup-ProviderService
           dbe9b383-7cf3-4331-91cc-a3cb16a3b538:0x0001000000000000:0x4       : Microsoft-Windows-Winlogon
           de513a55-c345-438b-9a74-e18cac5c5cc5:0x0001000000000000:0x4       : Microsoft-Windows-Help
           ded165cf-485d-4770-a3e7-9c5f0320e80c:0x0001000000000000:0x4       : Microsoft-Windows-DeviceUx
           e978f84e-582d-4167-977e-32af52706888:0x0001000000000000:0x4       : Microsoft-Windows-TabletPC-InputPanel
           ed6b3ba8-95b2-4cf5-a317-d4af7003884c:0x0001000000000000:0x4       : Microsoft-Windows-Sidebar
           f3f14ff3-7b80-4868-91d0-d77e497b025e:0x0001000000000000:0x4       : Microsoft-Windows-WMP
           fbcfac3f-8459-419f-8e48-1f0b49cdb85e:0x0001000000000000:0x4       : Microsoft-Windows-NetworkProfile
           ffdb9886-80f3-4540-aa8b-b85192217ddf:0x0001000000000000:0x4       : Microsoft-PerfTrack-MSHTML

    We have a lot to play with as you can see, but let’s say you are trying to track down a socket leak.  Since we know sockets are implemented in afd.sys, let’s search for that provider…

    C:\utils\xperf7sdk>xperf -providers | findstr "AFD"        
    e53c6823-7bb8-44bb-90dc3f86090d48a6                               : Microsoft-Windows-Winsock-AFD       
    Microsoft-Windows-Winsock-AFD


    Now, we can form the XPerf syntax to trace socket operations during the leak.  The “AFDSession” is just the session name we are making up, the rest is the prescriptive syntax. Just to explain the syntax we are starting multiple sessions at the time here – kernel logger session + AFDSession. Similarly we are stopping both sessions at the same time and then merging both into the one file AFD.etl file.

    xperf -on Latency -stackwalk profile -start AFDSession -on Microsoft-Windows-Winsock-AFD:::'stack'
    <reproduce leak>
    xperf -stop AFDSession -stop -d AFD.etl

    Run xperfview AFD.etl and switch on “Stack counts by type graph”. If you don’t see this frame, make sure you are on the 7SDK version

    clip_image001

    The beauty here is the Stack Counts by Type frame which allows us to explore which stack traces where collected, notice all the AFD stack count sources!

    clip_image002

    Let’s say we have the simple case of a massive number of Create’s happening and thus handle counts rocketing up (leaking) for a given process.  Perhaps exhausting all ephemeral ports on the system, ultimately resulting in any number of hang symptoms.

    Simply filter the Events for AfdCreate as follows.

    clip_image003

    Now, we have a filtered Frame of just those stack counts….

    clip_image004

    You can imagine that if there were a lot more creates here that the frequency distribution shown above would be much higher, but for the sake of just exploring the feature, let’s just look at these small number of creates anyway.  In fact, let’s select them all by just choosing Select View in the context menu which will get all of these events over the trace sample.

    clip_image005

    The frame area is now highlighted in light purple indicating the selected area.

    clip_image006

    Because we are interested in Stacks, make sure you have configured your symbol path and have checked Load Symbols

    (be patient, this could take a while to build up your symbol cache)

    clip_image007

    clip_image008

    Next, invoke the Summary Table

    clip_image009

    Click the flyout control on the left to select only the Creates again.

    clip_image010

    Next, make it easy on yourself by Filtering on the interesting process only.

    clip_image011

    After, much better.

    clip_image012

    Now, here is the fruit of our labor in the full stack trace inside iexplore.exe allocating the socket handles.

    clip_image013

    Continued…

    clip_image001[5]

     

    Consider that what we see above is read from the top down.  Iexplore.exe is doing this work through wininet, jsproxy, jscript, etc. all the way down through the calling of ws2_32.dll!socket which ultimately creates the socket and returned our file handle.  I’ve seen so many cases of ephemeral port exhaustion which is essentially a handle leak against sockets, these could have been solved in minutes with this tracing!  Keep in mind that this data isn’t perfectly suited for tracking handle leaks, especially small ones since there’s no accounting for outstanding handles.  However, sometimes the leak is egregious enough that you just need to look at activity over time to be pretty certain of the culprit.  Really, what we are doing here is just probing a particular ETW instrumented API, which is incredibly powerful.

    Typically, on 64-bit computers, you cannot capture the kernel stack in certain contexts when page faults are not allowed. To enable walking the kernel stack on AMD64, set the DisablePagingExecutive Memory Management registry value to 1 and reboot. The DisablePagingExecutive registry value is located under the following registry key: HKLM\System\CurrentControlSet\Control\Session Manager\Memory Management

    In summary, this isn’t really a hidden feature since it’s documented in EnableTraceEx2’s Enable Parameters parameter, but I hope with this additional context you see what powerful analysis is possible.  Previously, this would have required live debugging a process, so now we have another example of the power of XPerf to decode and view key system activity, non-invasively!

    -Tate

Page 1 of 1 (3 items)