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.
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.
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 boxNT Kernel Logger Windows Kernel Trace Kernel Logger used by XPerf but can be enabled manually w/o XPerf
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.
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.
Using the !wmitrace.strdump debugger extension, we can find the Logger Id for the CKCL which is 2.
And use !wmitrace.logsave to save the log to an ETL file
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.
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
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.
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.
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
logman stop "NT Kernel Logger" -ets
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:
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
logman delete customTrace
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.
To create a new session, right click Event Trace Sessions and choose New -> Data Collector Set
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.
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.
Which we should find in the GUI of Event providers:
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.
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.
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.
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!
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.
Now when creating a new trace with the GUI we can use a template to capture the previous saved settings, and quickly setup tracing.
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.
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
tracelog -start critSecTrace -f c:\temp\critSecTrace.etl -critsec -pids 1 7752
logman -stop critSecTrace
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.
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.
tracelog -start heapTrace -f c:\temp\heapTrace.etl -heap -pids 1 7752
logman -stop heapTrace
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’
xperf -start HeapSession -heap -PidNewProcess "notepad.exe" -BufferSize 1024 -MinBuffers 128 -MaxBuffers 128 -stackwalk HeapAlloc+HeapRealloc
xperf -stop HeapSession -stop -d c:\temp\xperf_heap.etl
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!
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 :
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 fa808000Pool 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) NtFs3: kd> !pool fa550000Pool 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 f8feb000Pool 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) MmCmfe593000 size: f18 previous size: 0 (Allocated) MmCmfe597000 size: f18 previous size: 0 (Allocated) MmCmfe5ac000 size: f18 previous size: 0 (Allocated) MmCmfe5ad000 size: f18 previous size: 0 (Allocated) MmCmfe5ae000 size: f18 previous size: 0 (Allocated) MmCmfe5af000 size: f18 previous size: 0 (Allocated) MmCmfe5b0000 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:
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.
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> dps b8ae6000 b8ae9000
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.
b8ae6100 b8ae6128 This points to the next frame
b8ae6104 f7a2ec45 fltmgr!FltpDispatch+0x6f <----possible return address
b8ae6124 8084cff9 nt!MmIsAddressValid+0xf
b8ae612c 8081df65 nt!IofCallDriver+0x45
b8ae6140 b958e196 BossHog+0x1196
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
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
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:,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
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
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.
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:
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
“Windows Internals, Fifth Edition” By Mark E. Russinovich, David A. Solomon, with Alex Ionescu
Chapter 9, page 786, “Kernel Stacks”
Share this post :