• Ntdebugging Blog

    Part 3: ETW Methods of Tracing

    • 1 Comments

    Introduction and Overview

     

    This is Ivan from the Platforms OEM team and this is the final installment of the ETW series. In this article, we are going to continue our exploration of the ETW tracing available in Windows. This post is going to cover some of the other methods available to enable and capture ETW logs. In previous posts we covered

     

    -ETW Introduction and Overview
    -Exploring and Decoding ETW Providers using Event Log Channels

    In this post we will explore some of the methods Microsoft support may use to enable and capture tracing, in order to troubleshoot issues on a box. In fact, some of these methods may ultimately be quite transparent when you use them; but we wanted to dig a bit into what his happening behind the scenes.

    Please keep in mind that the previous post, Exploring and Decoding ETW Providers using Event Log Channels, was geared more towards self-discovery and decoding. This post covers the more advanced scenarios and tools that you may see Microsoft support using.

    We plan on starting with some of what’s available in the box, then using a command line tool (logman) to enable further logging to a kernel buffer – both of these are useful for dumps. The second set of scenarios we are going to cover is using the command line (logman) and GUI to enable tracing to a sequential file. We will then finish up with some other special types of tracing available.

    Tracing already available (and likely running) in the box

     

    Starting with Vista/2008, there is a variety of tracing already running inbox and accessible via a kernel dump, or logging to an on-disk ETL file (limited tracing is available in 2003 & XP). This screenshot was taken from a default Vista box with no additional logging enabled or turned on. While we aren’t going to cover these ETW providers in detail, it’s good to know these are available for analysis. One logger in particular is a useful kernel logger, which is the Circular Kernel Context Logger or CKCL, a sort of In Flight Data Recorder (IFR). The CKCL is one of the two available kernel loggers, and is intended as a high-performance, high volume log to record the last 0.5-3 seconds (assuming high load) of low level kernel activity on the box. The CKCL is set to circular mode meaning newer events will overwrite older events, and with a 4MB total buffer space available.

    This can be very useful, because along with all the rich information a full kernel .dmp provides, the CKCL can enhance that and provide recent historical information about how the kernel arrived at the state it’s currently in. The CKCL is enabled by default in Vista and can be enabled in Server 2008 in the GUI or via the command line.

    image_thumb[3]

    The CKCL Keywords of 0x237f correspond to the following flags that are enabled on this box: process, thread, img, proccntr, cswitch, dpc, isr, disk, file, hf. The screenshot below shows information from the “NT Kernel Logger” session whose provider name is “Windows Kernel Trace”. “Windows Kernel Trace” is the provider for the CKCL and is shown here because it is the easiest/most reliable way to view what the kernel flags mean.

    The green boxes below highlight the flags that were automatically enabled on this Vista machine and available in dumps. You might notice that tools such as XPerf will modify and collect data from the “NT Kernel Logger” session. XPerf post processes/merges the trace (along with other potential providers) to add valuable information to be able read the trace in more human readable form as well as reliably view the trace offline. However, even without the post processing added by Xperf, traces can be pulled from kernel dump, decoded, and even viewed by Xperf (although they will be missing information such as process names, ISR names, symbol information, etc).

    To review how the kernel providers and sessions are related:

    Session                                                                                                 Provider                                               Comment____________________________

    Circular Kernel Context Logger(CKCL)                                     Windows Kernel Trace                   In-Flight Recorder for recent activity on the box
    NT Kernel Logger                                                                      Windows Kernel Trace                  Kernel Logger used by XPerf but can be enabled manually w/o XPerf

     

    Win7/2008R2:

    In order to cover the newer flags available, we illustrate the “NT Kernel Logger”, which is enabled because xperf was enabled with: xperf –on Base+Diag. To reiterate, the same flags are available in the CKCL, but whose configuration and purpose is suited toward an IFR scenario.

    image_thumb[34]

    image_thumb[35]

    image_thumb[36]

    Vista/2008:

    As covered in the picture above, the flags are very similar to Win7, with the exception that dispatcher and virtalloc are not available.

    Server 2003:
    ETW Tracing in 2003 is limited. You can see the Kernel Flags are much smaller and do not cover flags such as ISR or DPC.

    image_thumb[37]

    Using the !wmitrace.strdump debugger extension, we can find the Logger Id for the CKCL which is 2.

    image_thumb[38]

    And use !wmitrace.logsave to save the log to an ETL file

    image_thumb[39]

    Here we use Xperf to load the ETL file and are looking at ISR history over the lifetime of this particular trace (roughly last 250s of time before dump). This is a trace from a normally functioning box and is showing that ISR at 0x83b44b65 had the highest count over our selected ~100ms timeframe.

    image_thumb[40]

    As previously mentioned, you will need to hand decode much of the trace data, because the XPerf merge step is missing. Here we find that the ISR at 0x83b44b65 is from ndis!ndisMiniportIsr

    image_thumb[41]

    Finally, we can dump the log out in the debugger in plain old text format using !wmitrace.logdump, which we can decode because Windbg ships with a system.tmf which will decode most Kernel Events from the CKCL.

    image_thumb[42]

    Using Logman to enable tracing to a circular buffer

     

    Logman is a built in tool that ships with the OS in Vista/Win7, and can be used to enable and control ETW tracing. We are going to cover it first because it can be used to automate starting and stopping ETW logging without using the Computer Management GUI. It is also baked into the OS, making it ideal because no extra tools are required to start using or enabling ETW tracing. While logman is very useful, the syntax is often inconsistent, and it’s often difficult to figure out the right way to run a command, which is why we are going to cover some examples here.

    You may even receive a set of batch scripts that basically automate the starting and stopping of tracing. For example:

    -Start.bat <- Run this to start tracing
    -Stop.bat <- Run this to stop tracing

    Here we are using logman to start the tracing of the just previously mentioned “NT Kernel Logger” (used by XPerf) to enable the “Windows Kernel Trace” provider. This logging would be useful to enable kernel events that aren’t enabled by default in the CKCL, or if you want a larger time than the 4MB buffer the CKCL provides. The logging is flushed to disk after every 1MB buffer fills up.

    <Start.bat>

    REM – This creates a kernel trace using 20MB buffer in a circular file mode that logs to kernel.etl (and available in a memory dump as a circular buffer)

    logman start "NT Kernel Logger" -p "Windows Kernel Trace" (process,thread,disk,isr,dpc,net,img,registry,file) -bs 1024 -nb 20 20 -mode Circular -o kernel.etl -ct perf -max 20 -ets

    </Start.bat>

    <Stop.bat>

    logman stop "NT Kernel Logger" -ets

    </Stop.bat>

     

    Using Logman to enable tracing to a file

     

    You may receive logging scripts that are tuned specifically to the problem at hand, including the necessary providers, and within each provider, applicable Flags and Levels. In the previous blog posts, we already covered some information about how to find out providers, so we let’s assume we already have that information. Using logman to enable tracing in this manner allows for an ETW trace .etl to be captured and sent to Microsoft for decoding. Using the Microsoft-Windows-WinINet example, the tracing may look like this:

    <Start.bat>

    REM - This creates a circular file trace with all Flags and Levels on the Microsoft-Windows-WinINet provider, with a max size of 20MB

    logman start customTrace -o c:\temp\customTrace.etl -p "Microsoft-Windows-WinINet" 0xff 0xff -mode Circular -max 20 -ets

    REM This creates a file trace with all Flags and Levels on the Microsoft-Windows-WinINet provider, logging until stopped

    logman start customTrace -o c:\temp\customTrace.etl -p "Microsoft-Windows-WinINet" 0xff 0xff -ets

     </Start.bat>

    <Stop.bat>

    logman delete customTrace

    </Stop.bat>

    Using the Computer Management – Performance to enable tracing manually

     

    The Computer Management performance MMC GUI snap-in is useful for viewing and changing trace sessions. In previous blog posts, we briefly touched on the Event Trace Sessions GUI to view sessions auto-created when enabling a Windows Event log channel. Channels are useful because they don’t require much knowledge of the individual keywords/flags and levels to enable – they are pre-defined for a scenario. Most events that are delivered to a channel or decoded due to Event Manifests. However, there is another class of ETW providers called WPP Software Tracing, which was originally intended for driver tracing, but lacks a lot of the self-described meta information that manifest based providers give.

    This is where Computer Management -> Performance -> Data Collector Sets -> Event Trace Sessions, once again comes in handy. Not only can you view existing sessions created by the system (Autologgers/Start Event Trace Sessions), but you can modify tracing, and even create new tracing; which is what we are going to cover. This is the only way to create tracing using the GUI for WPP style ETW tracing, such as iSCSI.

    image_thumb[43]

    To create a new session, right click Event Trace Sessions and choose New -> Data Collector Set

    image_thumb[44]

    In our example, we already know what type of tracing to enable (you may be directed by Microsoft Support), or you may be given an .xml template to automatically setup the tracing. In our example, we are going to setup tracing for iSCSI, which is WPP based.

    image_thumb[45]

    The list of providers that displays unfortunately isn’t searchable, but is sorted alphabetically, so we can use our ‘logman query providers | findstr /I iscsi” to find providers named iscsi.

    image_thumb[46]

    Which we should find in the GUI of Event providers:

    image_thumb[47]

    Next we need to choose what Keywords (Any) are used for this provider. Keywords (Any) is an OR filter meaning any bit that is set on the Keyword/Flag mask will be traced. Keywords usually specify functional sub-components while Levels control at which level of detail (Error, Informational, Verbose) events are logged. Components are free to choose what Keywords/Flags they use, and what Levels the use; and don’t have to use both. We will need to set or check both Keywords(Any) and Level(s) in order to get any ETW tracing, otherwise events won’t be logged.

    image_thumb[48]

    When we edit Keywords (Any) to include these four flags, you should notice the mask is set automatically to 0xf, which will reflect under Keywords(Any). When we go to edit the level, we notice levels don’t seem to be exposed or used by the msisci_iScsi provider. That normally means a provider doesn’t use levels, but it is recommended to always be on the safe side, so to make sure not to lose events we can set the level anyways. Here we set the level to 0xff.

    image_thumb[49] image_thumb[50]

     

    image_thumb[51]

    What we should have now is a trace session called iSCSI with the msisci_iSCSI provider with Keywords(Any) of 0xf and Level of 0xf. There are just a couple of more items we need to check before starting to collect data on this provider, while is changing the Trace Buffer parameters, and checking stream mode and log location.

    image_thumb[52] image_thumb[53] image_thumb[54]

    Here we change the Buffer Size to 1MB, flushed to disk every second, with 10 buffers available in case there is so much event load that events can’t be flushed to disk fast enough. We simply check the Stream Mode and see it is set to File, and check the file name which is under %LOCALAPPDATA%\iSCSI.etl. Now we can start the ETW session and start collecting data!

    image_thumb[55]

    Using the Computer Management – Performance to enable tracing with a template

     

    Now, while it’s useful to know how to manually create sessions, either with the GUI or logman command line; you may only want to quickly enable tracing provided by someone else, such as Microsoft Support, or save off commonly used tracing. This is where templates come in handy. Continuing with the last session, we can right click on our iSCSI session and choose “Save Template”, and then save the template as iSCSI.xml.

    image_thumb[56] image_thumb[57]

    Now when creating a new trace with the GUI we can use a template to capture the previous saved settings, and quickly setup tracing.

    image_thumb[58]

    Using tracelog (DDK) to enable tracing to a file

     

    Tracelog is an ETW tracing tool that ships with the DDK. It has some more advanced features than logman that ships with the OS, with a disadvantage that you will need to download the WDK/DDK. You will find tracelog under %DDK_INSTALL_DIR%\tools\tracing\%PROCESSOR_ARCHITECTURE%\tracelog.exe, along with other useful tools such TraceView, and tracefmt.

    While you can use the built-in Computer Management GUI or logman to manipulate most tracing, a couple of key features that tracelog provides are:

                    -Realtime output to the kernel debugger (-kd switch)
                    -Private process heap tracing (-heap -pids <n> <pid1 pid2 …>). Heap tracing is also available in xperf, and is more useful due to stack walking (more on this later)
                    -Private process critical section tracing (-critsec -pids <n> <pid1 pid2 …>)
                    -Ability to create autologgers/traces that persist on reboots (-addautologger). Note: This ability does exist in logman, but is hidden. It can be done by appending “autosession\” to the name of session using logman.

    Here we are going to use tracelog to demonstrate a special type of logger in ETW called a private session logger, which uses private buffers inside a process (normally ETW buffers live in kernel mode). Private buffers are the only way to collect heap or critical section ETW tracing.

    Critical section private tracing

    First we start by finding the notepad process, for which we are going to collect critical section tracing.

    C:\temp>tasklist | findstr /i notepad

    Image Name                     PID Session Name        Session#    Mem Usage
    ========================= ======== ================ =========== ============
    notepad.exe                  7752 Console                    2     10,052 K

    Now we use tracelog with the –critsec switch to

    <Start.bat>

    tracelog -start critSecTrace -f c:\temp\critSecTrace.etl -critsec -pids 1 7752

    </Start.bat>

    <Stop.bat>

    logman -stop  critSecTrace

    </Stop.bat>

    The critical section trace can be decoded with the DDK tracefmt tool using the system.tmf in the DDK. Here is an example portion of the decoded log.

    image_thumb[59]

    Heap private tracing

     

    We can use tracelog in a similar manner to enable and decode heap tracing. The heap trace can also be decoded with the DDK tracefmt tool using the system.tmf in the DDK.

    <Start.bat>

    tracelog -start heapTrace -f c:\temp\heapTrace.etl -heap -pids 1 7752

    </Start.bat>

    <Stop.bat>

    logman -stop  heapTrace

    </Stop.bat>

    image_thumb[60]

    While the heap trace is useful in its own right, we can even get more useful info using XPerf. Xperf is a great way to view most types of ETW data (especially performance), and in this particular case is vital to get full stack traces that led up to the heap entries. Xperf can be downloaded from the Windows Performance Analysis Dev Center. Here we enable stacktraces for heap allocations and reallocations so we know who is creating the heaps. You may want to explore other heap stackwalking available with the xperf help -  ‘xperf -help stackwalk’

    image_thumb[32]

    <Start.bat>

    xperf -start HeapSession -heap -PidNewProcess "notepad.exe" -BufferSize 1024 -MinBuffers 128 -MaxBuffers 128 -stackwalk HeapAlloc+HeapRealloc

    </Start.bat>

    <Stop.bat>

    xperf -stop HeapSession -stop -d c:\temp\xperf_heap.etl

    </Stop.bat>

    Now we can load up the ETW trace in xperf, and view heap allocation information (in additional to kernel info such as CPU from the NT Kernel Logger), with stack traces at the time of allocation!

    image_thumb[61]

    Wrapping it up

     

    Hopefully, we dug further into ETW and explored some of the various methods to put the power of ETW to work. There is a lot of tools and power exposed with the built-in ETW tools, and some other scenarios that can be enabled with add-on tools from the DDK and XPerf.

     

    Share this post :

     

  • Ntdebugging Blog

    Pool Fragmentation

    • 3 Comments

    Hello! My name is Stephen, an escalation engineer on the Microsoft Global Escalation Services Team. Today I'm going to share my experience of a pool fragmentation issue I came across recently. Let’s jump right in with the dump file.

    This is the output of !vm

    *** Virtual Memory Usage ***

          Physical Memory:      917368 (   3669472 Kb)
          Page File: \??\C:\pagefile.sys
            Current:   4190208 Kb  Free Space:   4090220 Kb
            Minimum:   4190208 Kb  Maximum:      4190208 Kb
          Available Pages:      649161 (   2596644 Kb)
          ResAvail Pages:       860271 (   3441084 Kb)
          Locked IO Pages:         210 (       840 Kb)
          Free System PTEs:      14629 (     58516 Kb)
          Free NP PTEs:           4230 (     16920 Kb)
          Free Special NP:           0 (         0 Kb)
          Modified Pages:          791 (      3164 Kb)
          Modified PF Pages:       785 (      3140 Kb)
          NonPagedPool Usage:    25463 (    101852 Kb)
          NonPagedPool Max:      32647 (    130588 Kb)
          PagedPool 0 Usage:      8717 (     34868 Kb)
          PagedPool 1 Usage:      6113 (     24452 Kb)
          PagedPool 2 Usage:      6100 (     24400 Kb)
          PagedPool 3 Usage:      6033 (     24132 Kb)
          PagedPool 4 Usage:      6116 (     24464 Kb)
          PagedPool Usage:       33079 (    132316 Kb)
          PagedPool Maximum:     60416 (    241664 Kb)
          Session Commit:         1870 (      7480 Kb)
          Shared Commit:          5401 (     21604 Kb)
          Special Pool:              0 (         0 Kb)
          Shared Process:         8957 (     35828 Kb)
          PagedPool Commit:      33120 (    132480 Kb)
          Driver Commit:          1939 (      7756 Kb)
          Committed pages:      227031 (    908124 Kb)
          Commit limit:        1929623 (   7718492 Kb)

    Using the!poolused /t5 2, I dumped out the highest users of nonpaged pool.


       Sorting by  NonPaged Pool Consumed
      Pool Used:
                NonPaged            Paged
     Tag    Allocs     Used    Allocs     Used
     MmCm     3187 17452976         0        0      Calls made to MmAllocateContiguousMemory , Binary: nt!mm
     NDpp     1125  4519648         0        0      packet pool , Binary: ndis.sys
     File    24911  3992376         0        0      File objects
     abcd        8  3305504         0        0      UNKNOWN pooltag 'abcd', please update pooltag.txt
     LSwi        1  2576384         0        0      initial work context
     TOTAL  239570 65912104    200276 66610504

    The big difference between the totals reported by !vm(101 MB) and !poolused(65 MB), tells us there is a pool fragmentation issue!

    After some research, I found a lot of pool pages with the following allocation pattern:

    3: kd> !pool fa808000
    Pool page fa808000 region is Nonpaged pool
    *fa808000 size:  a20 previous size:    0  (Free)      *MFE0
     fa808a20 size:   18 previous size:  a20  (Allocated)  ReEv
     fa808a38 size:  5c8 previous size:   18  (Free)       NtFs

    3: kd> !pool fa550000
    Pool page fa550000 region is Nonpaged pool
    *fa550000 size:  860 previous size:    0  (Free)      *Io 
     fa550860 size:   18 previous size:  860  (Allocated)  MFE0
     fa550878 size:  788 previous size:   18  (Free)       Irp

    3: kd> !pool f8feb000
    Pool page f8feb000 region is Nonpaged pool
    *f8feb000 size:  648 previous size:    0  (Free)      *Ntfr
     f8feb648 size:   18 previous size:  648  (Allocated)  ReEv
     f8feb660 size:  9a0 previous size:   18  (Free)       MFE0

    The page fa808000 has only one pool chunk in use, and its size is about 0x18=24 Bytes. The top and bottom portion of the entire page are freed pool chunks and could be re-allocated for any use. For this page, 24 out of 4096 bytes are in use.

    It is the same story on pages at fa550000, f8feb000, etc. So, the question is, how could this have happened and how do we avoid this in the future?

    From the dump, I also found many MmCm pool allocations:


    fe592000 size:  f18 previous size:    0  (Allocated) MmCm
    fe593000 size:  f18 previous size:    0  (Allocated) MmCm
    fe597000 size:  f18 previous size:    0  (Allocated) MmCm
    fe5ac000 size:  f18 previous size:    0  (Allocated) MmCm
    fe5ad000 size:  f18 previous size:    0  (Allocated) MmCm
    fe5ae000 size:  f18 previous size:    0  (Allocated) MmCm
    fe5af000 size:  f18 previous size:    0  (Allocated) MmCm
    fe5b0000 size:  f18 previous size:    0  (Allocated) MmCm
    ...

    This is most likely how the fragmentation happened

    1)  A driver requests a pool block of size 0xF18. Notice the 3 pages I displayed above have enough free space in total. The free blocks inside one page are split in two, one in the top, and the one in the bottom. Neither the top nor the bottom are big enough for the pool request of size 0xF18.

    2)  So the OS creates a new pool page, gives the top portion to the driver, and the bottom will be marked as freed pool.

    3)  Now there is a request for a small pool allocation. The OS might take the new pool page’s bottom portion to satisfy the request.

    4)  Now, the driver frees the MmCm pool usage. The bottom portion is still in use so the whole page could not be freed. As time goes on, it is very possible that some other portion will be re-allocated for some use.

    5)  Now, there is another request for a pool block of size 0xF18. The previous pool block is not good because there might be pool allocations in it. So the OS might create another new page again.

    6)  If the above things happen repeatedly, it has the potential to contribute to pool fragmentation as evident in this crash memory dump.

    Ways to avoid this issue - Instead of requesting an allocation of size 0xf18, the driver should request an entire page. There will be some small wasted portion in the page, but that is the trade-off to avoid this type of fragmentation issue. By the way, MSDN suggests drivers should use the MmCm for long term. In a live debug, you will see the driver continually allocating and freeing MmCm.

    Links to related article:

    http://msdn.microsoft.com/en-us/library/ms801986.aspx


    http://blogs.msdn.com/ntdebugging/archive/2006/12/18/Understanding-Pool-Consumption-and-Event-ID_3A00_--2020-or-2019.aspx


     

  • Ntdebugging Blog

    Part 2: Got Stack? No. We ran out and kv won’t tell me why!

    • 2 Comments

    Hello. It’s Ryan again with the second installment of my stack depletion walkthrough.  Part 1 of this blog covered the initial analysis of a kernel memory dump captured due to a Stop 0x7f EXCEPTION_DOUBLE_FAULT.  Our initial analysis revealed that kv was not able to provide us with a useful stack backtrace. Background information relating to Task States and Double Faults were also covered. If you haven’t yet reviewed this blog, you can find it at Part 1. 

     

    Previously, in part one of this blog, we reviewed the memory dump of a stop 0x7f EXCEPTION_DOUBLE_FAULT  and found that we were not provided with a valid stack backtrace. Without a valid stack backtrace, we were unable to identify what depleted the stack. Whenever I am in the situation where kv is not able to properly walk the stack, my next course of action is to manually dump out the memory within the stack range using the dps command.

     

    In the previous blog, we ran the !thread command to obtain the stack base and limit to view the thread in our fictiously named process, StackHog.exe.

     

    !thread   

    Owning Process            874c6800       Image:         StackHog.exe  

    ...

    Base b8ae9000 Limit b8ae6000

     

    Let’s pass this address range to the dps command. The dps command will display the contents of memory and treat the data dumped out as pointers. It will then try to match up these pointer addresses with symbol information in the same manner that kv does.

     

    dps  b8ae6000 b8ae9000

    .

    .

    .

     

    omitting extremely long output

     

    I'll spare the lengthy dps output here and instead describe what was observed.  When dumping the stack in this manner, I noticed that one product’s drivers were appearing on the stack over and over again. This product also provided the executable that was running as the current process (I obtained this information from the !thread command that I ran to obtain the limit and base values).   Running lm kv m and !lmi against these drivers verified that they were in fact all from the same product (StackHog.exe). 

     

    Using dps in this manner will often provide a good idea of what may have been using the stack. However, there are a few problems that may affect the reliability of this method. Dps simply dumps out whatever data is present anywhere on the stack.  One problem is there can often be trash left over on the stack from previous activity that is unrelated to our present stack. Also, there may be trap handlers and other data that shows up to further complicate the call flow picture. In addition, the information will not clearly show the order of calls like a kv stack backtrace output will. The output can also be very lengthy since the entire range is displayed. On a stack where each call frame averages 8 frames, you may be only interested in the symbols from the return address in each frame. I have observed some stack frames where dps may resolve two or three symbols for that frame.  All of this means that while dps is a good tool and often useful, on occasion some of the output from dps may be confusing instead of revealing.  Sometimes when multiple unrelated code from various vendors (including Microsoft) are on the stack, you may need a more complete understanding of the true call flow.  For these reasons, whenever possible, I want to be able to see the kv stack backtrace to display the call flow that led up to the crash. 

     

    Let's see if we can help kv to reconstruct the stack. Since the stack backtrace did not display properly on its own, we will need to help out a little to get the backtrace started. If we can provide  good starting point  values, the debugger can often dump out the rest of the stack. Also, when dealing with an overflowed stack, we will want to use the kf option instead of kv.  The kf command will give us a better idea of how much space a driver and the calls it made are occupying on the stack.  It does this by listing the amount of stack space between the stack frames. If you take these stack usage values as fact, you are assuming that the stack was backtraced correctly. Sometimes this isn’t the case when you don’t have symbols for all the code on the stack.  So to investigate the stack usage, we need to get a good backtrace. The k command accepts parameters that will help it display the stack using address values that you provide. We need to provide a few addresses to any of the various versions of the k command by using the equal sign as I will demonstrate shortly. We need to provide the BasePtr, the StackPtr, and the InstructionPtr.   For more information on the k command, refer to the msdn documentation .

    Since the real problem here is that various modules have used up all the stack, we simply need to dump out most of that stack to see where most of the usage is. It isn't important that we identify what was going on when we died or what was at the very top of the stack. We just want to see as much of the stack as we can dumped out in an easy to understand format by using kf. 

     

     So where can we find these values? I'll start by dumping out the stack using the address of the stack limit. Let's dump out this area of memory. I'll start by clearing the screen so that I can examine the output

     

    3: kd>.cls

     

    3: kd> dps  b8ae6000 b8ae9000

     

                                   <omitting output>

     

    I wasn’t able to locate any valid patterns in the very top of the stack. This was probably due to lack of symbols and valid stack related register addresses combined with FPO or other optimizations. Things started making sense further down the stack in the stack range that I have listed below. Observe the patterns I have highlighted. Note that the symbol output is listed next to the return addresses. I will try to display my stack starting at this point. B8ae6100 is very close to the stack limit so we won’t be missing much of the output. We will get most of the stack output that we need to see if we start here.

     

     

    b8ae60ec  b8ae6100    <----------------------------------points to the next stack frame pointer (saved ebp) below

    b8ae60f0  8081df65 nt!IofCallDriver+0x45 <---possible Return address. Start here.

    b8ae60f4  8763f718

    b8ae60f8  87758bd8

    b8ae60fc  8b4abb00

    b8ae6100  b8ae6128     This points to the next frame

    b8ae6104  f7a2ec45 fltmgr!FltpDispatch+0x6f <----possible return address

    b8ae6108  8b4abb00

    b8ae610c  87758bd8

    b8ae6110  00000000

    b8ae6114  89751350

    b8ae6118  00000080

    b8ae611c  00000000

    b8ae6120  b8ae6130

    b8ae6124  8084cff9 nt!MmIsAddressValid+0xf

    b8ae6128  b8ae613c

    b8ae612c  8081df65 nt!IofCallDriver+0x45

    b8ae6130  8765b6a8

    b8ae6134  87758bd8

    b8ae6138  89751350

    b8ae613c  b8ae6144

    b8ae6140  b958e196 BossHog+0x1196

    b8ae6144  b8ae61c4

    b8ae6148  b958f4bc BossHog!StackEater+0x80c

     

    I'll start by identifying all of the stack address in the hopes of finding any candidates for saved stack frame pointers (saved ebp values). Based on the limit and base, these addresses will all start with b8ae. The next digit will be 6, 7, 8, or 9.  I have identified all of the possible values. Next, I looked for patterns of addresses that are pointing to other pointers below them to create a chain.  Next, I will look for possible return addresses. They should appear on the line right under the saved EBP value.

     

    I'll try dumping the stack using the values from the first possible frame. The format is

     

    kf=BasePtr, StackPtr, InstructionPtr

     

    So now, it appears that we have a pattern, let me pass in these numbers to the kf command. If this works, then the stack walker will dump the stack out from this point down up to the maximum that you have set by using the .kframes command. I’ll start by raising the number of stack frames displayed using .kframes.

     

    3: kd> .kframes 200

     

    Default stack trace depth is 0n512 frames

     

    Now, lets dump the stack out using kf. Kf will display the number of bytes of stack space used in hex on each line before it displays the  frame.

     

    3: kd> kf=b8ae6100 b8ae60ec 8081df65

      Memory  ChildEBP RetAddr 

              b8ae6100 f7a2ec45 nt!IofCallDriver+0x45

           28 b8ae6128 8081df65 fltmgr!FltpDispatch+0x6f

           14 b8ae613c b958e196 nt!IofCallDriver+0x45

    WARNING: Stack unwind information not available. Following frames may be wrong.

            8 b8ae6144 b958f4bc BabyHog+0x1196

           80 b8ae61c4 8081df65 BabyHog!HogFarm+0x88c

           14 b8ae61d8 b80c18a6 nt!IofCallDriver+0x45

           84 b8ae625c b80cf367 BossHog+0x78a6

           10 b8ae626c b80cf3b7 BossHog+0x15367

           28 b8ae6294 8081df65 BossHog!DEVICEDISPATCH::DispatchPassThrough+0x48

           14 b8ae62a8 b76fbcf7 nt!IofCallDriver+0x45

           84 b8ae632c b7709ae6 BossHog01+0x7cf7

           10 b8ae633c b7709b36 BossHog01+0x15ae6

           28 b8ae6364 8081df65 BossHog01!DEVICEDISPATCH::DispatchPassThrough+0x48

           14 b8ae6378 8081e4ed nt!IofCallDriver+0x45

           18 b8ae6390 8085114a nt!IoPageRead+0x109

           9c b8ae642c 8085ea66 nt!MiDispatchFault+0xece

           84 b8ae64b0 8088c798 nt!MmAccessFault+0x89e

            0 b8ae64b0 808b64a6 nt!_KiTrap0E+0xdc

           c8 b8ae6578 bae5af2d nt!CcMapData+0x8c

           20 b8ae6598 bae5849b Ntfs!NtfsMapStream+0x4b

           74 b8ae660c bae5adf0 Ntfs!NtfsReadMftRecord+0x86

           38 b8ae6644 bae5afac Ntfs!NtfsReadFileRecord+0x7a

           38 b8ae667c bae19903 Ntfs!NtfsLookupInFileRecord+0x37

          110 b8ae678c bae1a6c4 Ntfs!NtfsLookupAllocation+0xdd

          1d0 b8ae695c bae1a87c Ntfs!NtfsPrepareBuffers+0x25d

          1dc b8ae6b38 bae1b1a6 Ntfs!NtfsNonCachedIo+0x1ee

           ec b8ae6c24 bae1b0c9 Ntfs!NtfsCommonRead+0xaf5

          1ac b8ae6dd0 8081df65 Ntfs!NtfsFsdRead+0x113

           14 b8ae6de4 f7a2ec45 nt!IofCallDriver+0x45

           28 b8ae6e0c 8081df65 fltmgr!FltpDispatch+0x6f

           14 b8ae6e20 b958e196 nt!IofCallDriver+0x45

            8 b8ae6e28 b958f4bc BabyHog+0x1196

           80 b8ae6ea8 8081df65 BabyHog!HogFarm+0x88c

           14 b8ae6ebc b80c18a6 nt!IofCallDriver+0x45

           84 b8ae6f40 b80cf367 BossHog+0x78a6

           10 b8ae6f50 b80cf3b7 BossHog+0x15367

           28 b8ae6f78 8081df65 BossHog!DEVICEDISPATCH::DispatchPassThrough+0x48

           14 b8ae6f8c b76fbcf7 nt!IofCallDriver+0x45

           84 b8ae7010 b7709ae6 BossHog01+0x7cf7

           10 b8ae7020 b7709b36 BossHog01+0x15ae6

           28 b8ae7048 8081df65 BossHog01!DEVICEDISPATCH::DispatchPassThrough+0x48

           14 b8ae705c 8081e4ed nt!IofCallDriver+0x45

           18 b8ae7074 8085114a nt!IoPageRead+0x109

           9c b8ae7110 8085ea66 nt!MiDispatchFault+0xece

           84 b8ae7194 8088c798 nt!MmAccessFault+0x89e

            0 b8ae7194 808b64a6 nt!_KiTrap0E+0xdc

           c8 b8ae725c bae5af2d nt!CcMapData+0x8c

           20 b8ae727c bae5d9d5 Ntfs!NtfsMapStream+0x4b

           30 b8ae72ac bae5f5e4 Ntfs!ReadIndexBuffer+0x8f

          174 b8ae7420 bae5f786 Ntfs!NtfsUpdateFileNameInIndex+0x62

           fc b8ae751c bae5f8c6 Ntfs!NtfsUpdateDuplicateInfo+0x2b0

          208 b8ae7724 bae5c8d9 Ntfs!NtfsCommonCleanup+0x1e82

          170 b8ae7894 8081df65 Ntfs!NtfsFsdCleanup+0xcf

           14 b8ae78a8 f7a2ec45 nt!IofCallDriver+0x45

           28 b8ae78d0 8081df65 fltmgr!FltpDispatch+0x6f

           14 b8ae78e4 b958e196 nt!IofCallDriver+0x45

            8 b8ae78ec b958f472 BabyHog+0x1196

           80 b8ae796c 8081df65 BabyHog!HogFarm+0x842

           14 b8ae7980 b80c18a6 nt!IofCallDriver+0x45

           84 b8ae7a04 b80cf367 BossHog+0x78a6

           10 b8ae7a14 b80cf3b7 BossHog+0x15367

           28 b8ae7a3c 8081df65 BossHog!DEVICEDISPATCH::DispatchPassThrough+0x48

           14 b8ae7a50 b770a8ac nt!IofCallDriver+0x45

           28 b8ae7a78 b76fb994 BossHog01!DEVICEDISPATCH::LowerDevicePassThrough+0x48

           7c b8ae7af4 b76fbbaf BossHog01+0x7994

           94 b8ae7b88 b7709ae6 BossHog01+0x7baf

           10 b8ae7b98 b7709b36 BossHog01+0x15ae6

           28 b8ae7bc0 8081df65 BossHog01!DEVICEDISPATCH::DispatchPassThrough+0x48

           14 b8ae7bd4 808f9732 nt!IofCallDriver+0x45

           30 b8ae7c04 80934bac nt!IopCloseFile+0x2ae

           30 b8ae7c34 809344ad nt!ObpDecrementHandleCount+0xcc

           28 b8ae7c5c 80934546 nt!ObpCloseHandleTableEntry+0x131

           44 b8ae7ca0 80934663 nt!ObpCloseHandle+0x82

           10 b8ae7cb0 8088978c nt!NtClose+0x1b

            0 b8ae7cb0 8082e811 nt!KiFastCallEntry+0xfc

           7c b8ae7d2c b8d8ec2d nt!ZwClose+0x11

           50 b8ae7d7c b8d8ede5 MamaHog+0x5c2d

           54 b8ae7dd0 b8d8fa85 MamaHog+0x5de5

          164 b8ae7f34 b8d917fe MamaHog+0x6a85

           40 b8ae7f74 b8d8d22a MamaHog+0x87fe

          2c4 b8ae8238 b958ecdf MamaHog+0x422a

           24 b8ae825c b958eee0 BabyHog!HogFarm+0xaf

           34 b8ae8290 8081e103 BabyHog!HogFarm+0x2b0

           30 b8ae82c0 bae1a22c nt!IopfCompleteRequest+0xcd

           10 b8ae82d0 bae5c00a Ntfs!NtfsCompleteRequest+0xc8

          104 b8ae83d4 8081df65 Ntfs!NtfsFsdCreate+0x48c

           14 b8ae83e8 f7a3c458 nt!IofCallDriver+0x45

           2c b8ae8414 8081df65 fltmgr!FltpCreate+0xe4

           14 b8ae8428 b958e196 nt!IofCallDriver+0x45

            8 b8ae8430 b958f71c BabyHog+0x1196

           60 b8ae8490 8081df65 BabyHog!HogFarm+0xaec

           14 b8ae84a4 b80d012b nt!IofCallDriver+0x45

           28 b8ae84cc b80c1862 BossHog!DEVICEDISPATCH::LowerDevicePassThrough+0x48

           8c b8ae8558 b80cf367 BossHog+0x7862

           10 b8ae8568 b80cf3b7 BossHog+0x15367

           28 b8ae8590 8081df65 BossHog!DEVICEDISPATCH::DispatchPassThrough+0x48

           14 b8ae85a4 b76f9639 nt!IofCallDriver+0x45

           4c b8ae85f0 b76fbb42 BossHog01+0x5639

           94 b8ae8684 b7709ae6 BossHog01+0x7b42

           10 b8ae8694 b7709b36 BossHog01+0x15ae6

           28 b8ae86bc 8081df65 BossHog01!DEVICEDISPATCH::DispatchPassThrough+0x48

           14 b8ae86d0 808f8f71 nt!IofCallDriver+0x45

           e8 b8ae87b8 80937942 nt!IopParseDevice+0xa35

           80 b8ae8838 80933a76 nt!ObpLookupObjectName+0x5b0

           54 b8ae888c 808eae25 nt!ObOpenObjectByName+0xea

           7c b8ae8908 808ec136 nt!IopCreateFile+0x447

           48 b8ae8950 b76ff4ae nt!IoCreateFileSpecifyDeviceObjectHint+0x52

           9c b8ae89ec b76ff0e6 BossHog01+0xb4ae

           58 b8ae8a44 b7685f8b BossHog01+0xb0e6

           50 b8ae8a94 b76867a3 daddyHog+0x3f8b

           28 b8ae8abc b76f66e7 daddyHog+0x47a3

           38 b8ae8af4 b76f6e76 BossHog01+0x26e7

          124 b8ae8c18 b770a0d5 BossHog01+0x2e76

           44 b8ae8c5c 808f5e2f BossHog01!DEVICEDISPATCH::DispatchPassThrough+0x5e7

           a4 b8ae8d00 808eed08 nt!IopXxxControlFile+0x255

           34 b8ae8d34 8088978c nt!NtDeviceIoControlFile+0x2a

            0 b8ae8d34 7c8285ec nt!KiFastCallEntry+0xfc

              0335e534 00000000 0x7c8285ec

     

    Problem solved, we have our stack. Please note that the technique demonstrated above is only applicable to an x86 platform. The x64 architecture is completely different. For more information, please refer to Trey Nash’s previous blog

     

    The same drivers I observed previously using the dps output are listed; however, it’s much easier to follow the call flow this time. Let’s see how much stack these hogs are using:

     

    3: kd> ? 0x8+0x80+0x84+0x10+0x28+0x84+0x10+0x28+0x8+0x80+0x84+0x10+0x28+0x84+0x10+0x8+0x80+0x84+0x10+0x28+0x28+0x7c+0x94+0x10+0x28+0x50+0x54+0x164+0x40+0x2c4+0x24+0x34+0x8+0x60+0x28+0x8c+0x10+0x28+0x9c+0x58+0x50+0x28+0x38+0x124+0x44

    Evaluate expression: 4176 = 00001050

     

    How many kb is this?

     

    3: kd> ? 4176/1024

    Evaluate expression: 4 = 00000004

     

    I would also like to dump out one of the functions that is using a large amount of stack space to show you how you can dig deeper into problems like this. Sometimes this level of granularity is needed when a vendor is attempting to optimize their code by showing them what caused their large allocations to occur.

     

    Let’s review the frame listed below that used 0x2c4 bytes of stack space

     

           40 b8ae7f74 b8d8d22a MamaHog+0x87fe

          2c4 b8ae8238 b958ecdf MamaHog+0x422a

           24 b8ae825c b958eee0 BabyHog!HogFarm+0xaf

     

    I have underlined the return address of this stack frame. This is the address right after the instruction where the call to MamaHog took place. After MamaHog would have completed, execution would of course have continued with the line of code right after the call. To view the call to MamaHog, let’s unassemble backwards one instruction to see the call being made.

     

    3: kd> ub b958ecdf  L1

    BabyHog!HogFarm+0xa8:

                 

    call    dword ptr BabyHog!HogFarm +0x7460 (b9596090)   <-stores the location we called

     

    Let’s dump out this location to see what we actually called. The code dereferences this location to make the actual call.

     

    3: kd> dps b9596090 L1

    b9596090  b8d8c0d0 BabyHog +0x30d0<-----highlighted address is the function called

     

    3: kd> uf b8d8c0d0

    b8d8c0d0 55              push    ebp               

    b8d8c0d1 8bec            mov     ebp,esp

    b8d8c0d3 6aff            push    0FFFFFFFFh

    b8d8c0d5 6840e2d9b8      push    offset BabyHog +0x15240 (b8d9e240)

    b8d8c0da 6808b2d9b8      push    offset BabyHog +0x12208 (b8d9b208)

    b8d8c0df 64a100000000    mov     eax,dword ptr fs:[00000000h]

    b8d8c0e5 50              push    eax

    b8d8c0e6 64892500000000  mov     dword ptr fs:[0],esp

    b8d8c0ed 81c470fdffff    add     esp,0FFFFFD70h         

     

    To subtract 656, we are adding -656 to esp to bump the stack up. This is where the compiler is allocating stack space for storage of local variables. I am guessing there were multiple structures being allocated directly on the stack.  If the programmer had instead called ExAllocatePoolWithTag to obtain memory, we could have instead only stored the pointers to this memory on the stack. Simply using the stack for storage is of course faster than calling out to get memory. The developer should balance the performance needs of the code with the need to conserve the stack space which is a limited resource.

     

    3: kd> .formats 0x0FFFFFD70

    Evaluate expression:

      Hex:     fffffd70

      Decimal: -656

     

    So this one instruction raised the stack more than .5 kb all by itself. The function made a bunch of other pushes (some of which are listed above) which when combined with the return address pushed by the call resulted in 708 (0x2c4 was listed by kf above) bytes of stack space to be allocated by this one function.

     

    3: kd> .formats 2c4

    Evaluate expression:

      Hex:     000002c4

      Decimal: 708

     

    Two allocations like this will use up almost 1.5kb of the 12k stack space. By itself, this isn’t necessarily an issue; however, you can see from the output above how liberal stack usage by multiple calls from stacked up drivers can quickly add up. So what have we discovered here? Without even considering the fact that this products drivers may also be responsible for some of the stack space used by calls that they may have initiated, they have used at least 4k of the 12k stack. Also, the full 12k of stack space is not available for driver use. This is because the operating system also requires stack space for such overhead as the I/O operation, the file system components, thread startup, etc. The customer removed the product which prevented further bugchecks while the vendor was being engaged to assist or provide leaner hogs.

     

    Summary

     

    This two part blog has covered CPU task states, stack overflows, x86 stack reconstruction techniques, and examining functions to observe the stack allocations taking place. Hopefully, this blog will help you to understand what went wrong the next time that you encounter a Stop 0x7f (EXCEPTION_DOUBLE_FAULT).

     

    You don’t have to wait until you encounter an UNEXPECTED_KERNEL_MODE_TRAP (7f)  Arg1: 00000008, EXCEPTION_DOUBLE_FAULT to get familiar with this. Open up any dump file and see if you can find the limit and base. Then observe the values of your ebp and esp registers. If you are feeling truly geeky, dump the stack range out, identify patterns, and try passing various values to kf.

     

    Please check out our previous blog post on this topic:

    http://blogs.msdn.com/ntdebugging/archive/2008/02/01/kernel-stack-overflows.aspx

     

    Keep in mind that this two part blog has only discussed stop 0x7f bugchecks where Arg1 lists value 0x8 EXCEPTION_DOUBLE_FAULT. There are other causes for a 0x7f bugcheck. For more information, please refer to:

     

    314102  General Causes of STOP 0x0000007F Errors

     

     

    Bug Check 0x7F: UNEXPECTED_KERNEL_MODE_TRAP

     

     

    References:

    “Windows Internals, Fifth Edition” By Mark E. Russinovich, David A. Solomon, with Alex Ionescu

    Chapter 9, page 786, “Kernel Stacks”

    Share this post :

Page 1 of 1 (3 items)