• Ntdebugging Blog

    Using Xperf to investigate slow I/O issues



    Here’s another short video of the type of triage possible with Xperf, this time Bob shows us how to track down a slow I/O issue. Since I/O Manager is instrumented at IoCallDriver and IoCompleteRequest we can often use this information to diagnose a Slow I/O or SAN issue. The steps to enable the tracing are in the video description and here again below.




    Video Description: (http://www.youtube.com/watch?v=0h-i_EfzadA)

    Here's how you can use the Windows Performance Toolkit aka Xperf to investigate slow I/O issues on Windows 2008, Vista, and higher versions. Put the following into a batch file (modifying the -f to point the etl file generation elsewhere than the slow storage) and it will start a circular trace which can be stopped when the slow I/O occurs.

    @echo off

    xperf -on PROC_THREAD+LOADER+CSWITCH+FILENAME+FILE_IO+FILE_IO_INIT+DRIVERS -f kernel.etl -stackwalk CSwitch+DiskReadInit+DiskWriteInit+DiskFlushInit+FileCreate+FileCleanup+FileClose+FileRead+FileWrite -BufferSize 1024 -MaxBuffers 1024 -MaxFile 1024 -FileMode Circular

    echo Reproduce the problem now, hit any key to finish, collect Merged Etl file


    echo merging etl...

    xperf -d XperfSlowIOcir.etl

    @echo on


    Share this post :
  • Ntdebugging Blog

    How the Clipboard Works, Part 1


    Recently I had the opportunity to debug the clipboard in Windows, and I thought I’d share some of the things I learned.  The clipboard is one of those parts of Windows that many of us use dozens (hundreds?) of times a day and don’t really think about. Before working on this case, I had never even considered how it works under the hood.  It turns out that there’s more to it than you might think. In this first article, I’ll describe how applications store different types of data to the clipboard and how it is retrieved.  My next post will describe how applications can hook the clipboard to monitor it for changes.  In both, I’ll include debug notes to show you how to access the data from the debugger.


    Let’s start by discussing clipboard formats.  A clipboard format is used to describe what type of data is placed on the clipboard.  There are a number of predefined standard formats that an application can use, such as bitmap, ANSI text, Unicode text, and TIFF.  Windows also allows an application to specify its own formats. For example, a word processor may want to register a format that includes text, formatting, and images.  Of course, this leads to one problem, what happens if you want to copy from your word processor and paste into Notepad, which doesn’t understand all of the formatting and pictures?


    The answer is to allow multiple formats to be stored in the clipboard at one time.  When I used to think of the clipboard I thought of it as a single object (“my text” or “my image”), but in reality the clipboard usually has my data in several different forms.  The destination program gets a format it can use when I paste.


    So how does this data end up on the clipboard?  Simple, an application first takes ownership of the clipboard via the OpenClipboard function.   Once it has done that, it can empty the clipboard with EmptyClipboard.  Finally, it is ready to place data on the clipboard using SetClipboardData.  SetClipboardData takes two parameters; the first is the identifier of one of the clipboard formats we discussed above.  The second is a handle to the memory containing the data in that format. The application can continue to call SetClipboardData for each of the various formats it wishes to provide going from best to worst (since the destination application will select the first format in the list it recognizes).  To make things easier for the developer, Windows will automatically provide converted formats for some clipboard format types.  Once the program is done, it calls CloseClipboard.


    When a user hits paste, the destination application will call OpenClipboard and one of these functions to determine what data format(s) are available: IsClipboardFormatAvailable, GetPriorityClipboardFormat, or EnumClipboardFormats. Assuming the application finds a format it can use, it will then call GetClipboardData with the desired format identifier as a parameter to get a handle to the data.  Finally, it will call CloseClipboard.


    Now let’s take a look at how you can find what data being written to the clipboard using the debugger. (Note that all of my notes are taken from a Win7/2008 R2 system – so things might vary slightly in different versions of the OS.)   Since the clipboard is part of Win32k.sys, you’ll need to use a kernel debugger.  I like to use win32k!InternalSetClipboardData+0xe4 as a breakpoint.  The nice thing about this offset is that it is right after we’ve populated the RDI register with data from SetClipboardData in a structure known as tagCLIP.


    kd> u win32k!InternalSetClipboardData+0xe4-c L5


    fffff960`0011e278 894360          mov     dword ptr [rbx+60h],eax

    fffff960`0011e27b 8937            mov     dword ptr [rdi],esi

    fffff960`0011e27d 4c896708        mov     qword ptr [rdi+8],r12

    fffff960`0011e281 896f10          mov     dword ptr [rdi+10h],ebp

    fffff960`0011e284 ff15667e1900    call    qword ptr[win32k!_imp_PsGetCurrentProcessWin32Process (fffff960`002b60f0)]


    kd> dt win32k!tagCLIP

       +0x000 fmt              : Uint4B

       +0x008 hData            : Ptr64 Void

       +0x010fGlobalHandle     : Int4B


    Here’s what a call to SetClipboardData from Notepad looks like:

    kd> k

    Child-SP          RetAddr           Call Site

    fffff880`0513a940 fffff960`0011e14f win32k!InternalSetClipboardData+0xe4

    fffff880`0513ab90 fffff960`000e9312 win32k!SetClipboardData+0x57

    fffff880`0513abd0 fffff800`01482ed3 win32k!NtUserSetClipboardData+0x9e

    fffff880`0513ac20 00000000`7792e30ant!KiSystemServiceCopyEnd+0x13

    00000000`001dfad8 00000000`7792e494 USER32!ZwUserSetClipboardData+0xa

    00000000`001dfae0 000007fe`fc5b892b USER32!SetClipboardData+0xdf

    00000000`001dfb20 000007fe`fc5ba625 COMCTL32!Edit_Copy+0xdf

    00000000`001dfb60 00000000`77929bd1 COMCTL32!Edit_WndProc+0xec9

    00000000`001dfc00 00000000`779298da USER32!UserCallWinProcCheckWow+0x1ad

    00000000`001dfcc0 00000000`ff5110bc USER32!DispatchMessageWorker+0x3b5

    00000000`001dfd40 00000000`ff51133c notepad!WinMain+0x16f

    00000000`001dfdc0 00000000`77a2652d notepad!DisplayNonGenuineDlgWorker+0x2da

    00000000`001dfe80 00000000`77b5c521 kernel32!BaseThreadInitThunk+0xd

    00000000`001dfeb0 00000000`00000000ntdll!RtlUserThreadStart+0x1d


    So here, we can dt RDI as a tagCLIP to see what was written:

    kd> dt win32k!tagCLIP @rdi

       +0x000 fmt              : 0xd

       +0x008 hData            : 0x00000000`00270235 Void

       +0x010fGlobalHandle     : 0n1


    Fmt is the clipboard format. 0xd is 13, which indicates this data is Unicode text.  We can’t just ‘du’ the value in hData, however, because this is a handle, not a direct pointer to the data.  So now we need to look up the handle.  To do that, we need to look at a win32k global structure – gSharedInfo:

    kd> ?win32k!gSharedInfo

    Evaluate expression: -7284261440224 = fffff960`002f3520

    kd> dt win32k!tagSHAREDINFO fffff960`002f3520

       +0x000 psi              : 0xfffff900`c0980a70 tagSERVERINFO

       +0x008 aheList          : 0xfffff900`c0800000 _HANDLEENTRY

       +0x010 HeEntrySize      : 0x18

       +0x018 pDispInfo        : 0xfffff900`c0981e50 tagDISPLAYINFO

       +0x020ulSharedDelta     : 0

       +0x028 awmControl       : [31] _WNDMSG

       +0x218DefWindowMsgs     : _WNDMSG

       +0x228DefWindowSpecMsgs : _WNDMSG


    aheList in gSharedInfo contains an array of handle entries, and the last 2 bytes of hData multiplied by the size of a handle entry the address of our handle entry:

    kd> ?0x00000000`00270235 & FFFF

    Evaluate expression: 565 = 00000000`00000235

    kd> ??sizeof(win32k!_HANDLEENTRY)

    unsigned int64 0x18

    kd> ? 0xfffff900`c0800000 + (0x235*0x18)

    Evaluate expression: -7693351766792 = fffff900`c08034f8


    kd> dt win32k!_HANDLEENTRY fffff900`c08034f8

       +0x000 phead            : 0xfffff900`c0de0fb0 _HEAD

       +0x008 pOwner           : (null)

       +0x010 bType            : 0x6 ''

       +0x011 bFlags           : 0 ''

       +0x012 wUniq            : 0x27


    If we look in phead at offset 14, we’ll get our data (this offset may vary on different platforms):

    kd> du fffff900`c0de0fb0 + 0x14

    fffff900`c0de0fc4 "Hi NTDebugging readers!"


    Let’s consider one other scenario.  I copied some text out of Wordpad, and a number of SetClipboardData calls were made to accommodate different formats. The Unicode format entry looks like this:

    Breakpoint 0 hit


    fffff960`0011e284 ff15667e1900   call    qword ptr[win32k!_imp_PsGetCurrentProcessWin32Process (fffff960`002b60f0)]

    kd> dt win32k!tagCLIP @rdi

       +0x000 fmt              : 0xd

       +0x008 hData            : (null)

       +0x010fGlobalHandle    : 0n0


    hData is null!  Why is that?  It turns out that the clipboard allows an application to pass in null to SetClipboardData for a given format.  This indicates that the application can provide the data in that format, but is deferring doing so until it is actually needed.  Sure enough, if I paste the text into Notepad, which needs the text in Unicode, Windows sends a WM_RENDERFORMAT message to the WordPad window, and WordPad provides the data in the new format.  Of course, if the application exits before populating all of its formats, Windows needs all of the formats rendered.  In this case, Windows will send the WM_RENDERALLFORMATS message so other applications can use the clipboard data after the source application has exited.


    That’s all for now.  Next time we’ll look at how applications can monitor the clipboard for changes using two hooks.  If you want to know more about using the clipboard in your code, this is a great reference.


    -Matt Burrough


    Part 2 of this article can be found here:


  • Ntdebugging Blog

    Understanding NTFS Compression


    As our group’s file systems expert, I see most of the common problems associated with the use/misuse of NTFS compression.  Before you check the “Compress contents to save disk space” checkbox, it might be good to understand how this affects the happy little bits, bytes, & nibbles running around on the disk.

    Often backup applications receive ERROR_DISK_FULL errors attempting to back up compressed files and this causes quite a bit of confusion when there are still several gigabytes of free space on the drive.  Other issues may also occur when copying compressed files.  The goal of this blog is to give the reader a more thorough understanding of what really happens when you compress NTFS files.

    Compression Units…

    NTFS uses a parameter called the “compression unit” to define the granularity and alignment of compressed byte ranges within a data stream.  The size of the compression unit is based entirely on NTFS cluster size (refer to the table below for details).  In the descriptions below, the abbreviation "CU" is used to describe a Compression Unit and/or its size.

    The default size of the CU is 16 clusters, although the actual size of the CU really depends on the cluster size of the disk.  Below is a chart showing the CU sizes that correspond to each of the valid NTFS cluster sizes.

    Cluster Size Compression Unit Compression Unit (hex bytes)
    512 Bytes 8 KB 0x2000
    1 KB 16 KB 0x4000
    2 KB 32 KB 0x8000
    4 KB 64 KB 0x10000
    8 KB 64 KB 0x10000
    16 KB 64 KB 0x10000
    32 KB 64 KB 0x10000
    64 KB 64 KB 0x10000

    Native NTFS compression does not function on volumes where the cluster size is greater than 4KB, but sparse file compression can still be used.

    NTFS Sparse Files…

    The Sparse Files features of NTFS allow applications to create very large files consisting mostly of zeroed ranges without actually allocating LCNs (logical clusters) for the zeroed ranges.

    For the code-heads in the audience, this can be done by calling DeviceIoControl with the FSCTL_SET_SPARSE IO control code as shown below.

    BOOL SetSparse(HANDLE hFile)
               DWORD Bytes;
               return DeviceIoControl(hFile, FSCTL_SET_SPARSE, NULL, 0, NULL, 0, &Bytes, NULL);

    To specify a zeroed range, your application must then call the DeviceIoControl with the FSCTL_SET_ZERO_DATA IO control code.

    BOOL ZeroRange(HANDLE hFile, LARGE_INTEGER RangeStart, LONGLONG RangeLength)
                FILE_ZERO_DATA_INFORMATION  FileZeroData;
                DWORD Bytes;
                FileZeroData.FileOffset.QuadPart = RangeStart.QuadPart;
                FileZeroData.BeyondFinalZero.QuadPart = RangeStart.QuadPart + RangeLength + 1;
                return DeviceIoControl(  hFile,

    Because sparse files don't actually allocate space for zeroed ranges, a sparse file can be larger than the parent volume.  To do this, NTFS creates a placeholder VCN (virtual cluster number) range with no logical clusters mapped to them. 

    Any attempt to access a “sparsed” range would result in NTFS returning a buffer full of zeroes.  Accessing an allocated range would result in a normal read of the allocated range.  When data is written to a sparse file, an allocated range is created which is exactly aligned with the compression unit boundaries containing the byte(s) written.  Refer to the example below.  If a single byte write occurs for virtual cluster number VCN 0x3a, then all of Compression Unit 3 (VCN 0x30 - 0x3f) would become an allocated LCN (logical cluster number) range.  The allocated LCN range would be filled with zeroes and the single byte would be written to the appropriate byte offset within the target LCN.

    [...] - ALLOCATED
    (,,,) - Compressed
    {   } - Sparse (or free) range
       / 00000000000000000000000000000000000000000000000000000000000000000000000000000000
    VCN  00000000000000001111111111111111222222222222222233333333333333334444444444444444
       \ 0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef
                CU0             CU1            CU2             CU3             CU4
         {                                              }[..............]{              }
    Extents  {
        VCN = 0x0 LEN = 0x30                        CU0 - CU2
        VCN = 0x30 LEN = 0x10: LCN = 0x2a21f        CU3
        VCN = 0x10 LEN = 0x10                       CU4

    Below is a screen shot of a 2GB file that was created using the sparse file API’s.


    Notice that this volume is only 76.9 MB, yet it has a 2 GB file in the root folder.


    If we attempt to duplicate this sparse file with the COPY command, it fails.  This is because COPY doesn’t know how to duplicate the sparse attributes on the file, so it attempts to create a real 2GB file in the root of D:.  This can occur in production when attempting to move a large database file from one volume to another.  If you have a database application that uses sparse attributes, then it is a good practice to use the database software’s backup / restore features when moving the database to a different volume.


    Now let’s look at the file’s properties with the COMPACT utility.  Notice that the file shows up as compressed, and it has a huge compression ratio.


    If you go back and look at the file properties from EXPLORER, you will notice that there is no compression checkbox (or any other indication that the file is compressed).  This is because the shell does not check for the sparse bit on the file.


    In short, use caution when moving sparse files from one location to another.  Applications tell the file system the offsets of zeroed ranges, so you should always leave the management of sparse files to the application that created them.  Moving or copying the sparse files manually may cause unexpected results.

    NTFS Compression…

    Now that we have discussed sparse files, we will move on to conventional NTFS compression.

    NTFS compresses files by dividing the data stream into CU’s (this is similar to how sparse files work).  When the stream contents are created or changed, each CU in the data stream is compressed individually.  If the compression results in a reduction by one or more clusters, the compressed unit will be written to disk in its compressed format.  Then a sparse VCN range is tacked to the end of the compressed VCN range for alignment purposes (as shown in the example below).  If the data does not compress enough to reduce the size by one cluster, then the entire CU is written to disk in its uncompressed form.

    This design makes random access very fast since only one CU needs to be decompressed in order to access any single VCN in the file.  Unfortunately, large sequential access will be relatively slower since decompression of many CU’s is required to do sequential operations (such as backups).

    In the example below, the compressed file consists of six sets of mapping pairs (encoded file extents).  Three allocated ranges co-exist with three sparse ranges.  The purpose of the sparse ranges is to maintain VCN alignment on compression unit boundaries.  This prevents NTFS from having to decompress the entire file if a user wants to read a small byte range within the file.  The first compression unit (CU0) is compressed by 12.5% (which makes the allocated range smaller by 2 VCNs).  An additional free VCN range is added to the file extents to act as a placeholder for the freed LCNs at the tail of the CU.  The second allocated compression unit (CU1) is similar to the first except that the CU compressed by roughly 50%.

    NTFS was unable to compress CU2 and CU3, but part of CU4 was compressible by 69%.  For this reason, CU2 & CU3 are left uncompressed while CU4 is compressed from VCNs 0x40 to 0x44.  Thus, CU2, CU3, and CU4 are a single run, but the run contains a mixture of compressed & uncompressed VCNs.

    NOTE:  Each set of brackets represents a contiguous run of allocated or free space.  One set of NTFS mapping pairs describes each set of brackets.

    [...] - ALLOCATED
    (,,,) - Compressed
    {   } - Sparse (or free) range
       / 00000000000000000000000000000000000000000000000000000000000000000000000000000000
    VCN  00000000000000001111111111111111222222222222222233333333333333334444444444444444
       \ 0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef
               CU0             CU1             CU2             CU3             CU4
         (,,,,,,,,,,,,){}(,,,,,,){      }[...............................,,,,){         }
    Extents  {
        VCN = 0x0 LEN = 0xe : LCN = 0x29e32d        CU0
        VCN = 0xe LEN = 0x2                         CU0
        VCN = 0x10 LEN = 0x8 : LCN = 0x2a291f       CU1
        VCN = 0x18 LEN = 0x8                        CU1
        VCN = 0x20 LEN = 0x25 : LCN = 0x39dd49      CU2 - CU4
        VCN = 0x45 LEN = 0xb                        CU4

    Now we come to the part where we describe limitations of this design.  Below are some examples of what happens when things go wrong while reading / writing compressed files.

    Disk full error during a backup read operation or file copy…

    1. NTFS determines which compression unit is being accessed.
    2. The compression unit’s entire allocated range is read.
    3. If the unit is not compressed, then we skip to step 5.  Otherwise, NTFS would attempt to reserve (but not allocate) the space required to write the decompressed CU back to disk.  If insufficient free space exists on the disk, then the application might get an ERROR_DISK_FULL during the read.
    4. The CU would be decompressed in memory.
    5. The decompressed byte range would be mapped into cache and returned to the requesting application.
    6. If part of the CU is altered in cache…
      1. The reserved disk space from step 3 would become allocated space.
      2. The CU contents would be compressed and flushed back to the newly allocated region (the LCN location will usually not change).
      3. Any recoverable disk space within the CU would be freed.

    Failure to copy a large file to a compressed folder…

    This is the most common problem seen with compression, and currently the solution is to educate users about limitations.  NTFS compression creates approximately one file fragment for every 16 clusters of data.  Because the max cluster size allowed for standard compression is 4K, the largest compression unit allowed is 64KB.  In order to compress a 100 GB file into 64KB sections, you could potentially end up with 1,638,400 fragments.  Encoding 1,638,400 fragments becomes problematic for the file system and can cause a failure to create the compressed file.  On Vista and later, the file copy will fail with STATUS_FILE_SYSTEM_LIMITATION.  On earlier releases, the status code would be STATUS_INSUFFICIENT_RESOURCES.  If possible, avoid using compression on files that are large, or critical to system performance.

    I received feedback from the NTFS Principal Development Lead about this blog.  Fortunately, most of the feedback was good, but he asked that I add a maximum size recommendation.  According to our development team’s research, 50-60 GB is a “reasonable size” for a compressed file on a volume with a 4KB cluster size.  This “reasonable size” goes down sharply for volumes with smaller cluster sizes.

    Compressing .VHD (Virtual Hard Disk) files causes slow virtual machine performance…

    A popular hammer company received a call from a customer complaining “It sure hurts when I hit my thumb with your hammers!”  Likewise, if you compress .VHD files, it is going to be a painful experience, so please compress responsibly.

    Best Regards,

    Dennis Middleton “The NTFS Doctor”

  • Ntdebugging Blog

    How Windows Shuts Down


    Hi my name is Bryan,  I'm a escalation engineer on the Microsoft CPR platforms team.   A common problem scenario involves shutting down Windows. When troubleshooting problems during shut down we have to look at the Winlogon.exe process which can be tricky and must be done correctly.


    Troubleshooting Techniques


    Common Settings


    Settings that would affect how Windows shuts down are mostly in HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Winlogon, and are documented thoroughly at http://www.microsoft.com/technet/prodtechnol/windows2000serv/reskit/regentry/12314.mspx. The setting to really pay attention is:


    DisableCAD (REG_DWORD). When set to 1 the GINA will bypass the Ctrl-Alt-Del dialog and go straight to the logon prompt. The system cannot be shutdown when the logon prompt at the console is displayed.


    Another common setting that is sometimes needed for security reasons is in HKLM\SYSTEM\CurrentControlSet\Control\Session Manager\Memory Management.


    ClearPageFileAtShutdown (REG_DWORD). When set to 1 the memory manager will clear the paging file on shutdown. If the paging file is large this can significantly the time it takes for the system to shut down.


    Winlogon Event Notification


    Prior to Windows Vista/2008 Server, Winlogon Notification Packages can be used to reliably monitor the state of Winlogon. These are simple export DLLs that are registered with entry points for each event monitored by the package. Winlogon explicitly calls these entry points when a specific event occurs. Each package handles the notification within the context of the Winlogon process. Keep in mind that a bug in a notification package can cause problems in Winlogon and render the system inaccessible. You can find more information about Winlogon Notification Packages at http://msdn2.microsoft.com/en-us/library/aa380545.aspx.


    Starting with Windows Vista support for Winlogon Notification Packages has been pulled. Most of this functionality is still provided through SCM event notifications. See the following link for more information about this.




    You can find information about how to write a service here.




    However these notifications are performed asynchronously so the exact moment of each state within Winlogon cannot be reliably known.


    Winlogon Logging


    Winlogon logging is obtained by applying the checked build of Winlogon and setting the following registry values under HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Winlogon.


    DebugFlags (REG_SZ). This is a comma-separated list of debug flags to capture. The list of flags is Error, Warning, Trace, Init, Timeout, Sas, State, MPR, CoolSwitch, Profile, DebugLsa, DebugSpm, DebugMpr, DebugGo, Migrate, DebugServices, Setup, SC, Notify, and Job.


    LogFile (REG_SZ). This is the path to the log file where the events should be written. If this value is missing then the events are written to the debug port.


    These options can also be placed in the win.ini file. This option and other debug logging options for Winlogon can be found in these articles.




    Checked builds of Windows binaries are available through MSDN subscriptions. The checked binary applied to the system must match the service pack level of the system.


    When looking at the Winlogon logs there are three check points to identify. They are the three ExitWindowsEx calls made during shutdown. These log entries were made during a shutdown initiated with “shutdown –r –f –t 0”.


    328.372> Winlogon-Trace: Doing remote-initiated (Administrator) Reboot=true, Force=true

    328.372> Winlogon-Trace: Starting user thread for Logoff, flags = 3807

    328.764> Winlogon-Trace: Doing immediate shutdown, LastGinaRet = b, Flags = 3804

    328.764> Winlogon-Trace: Calling ExitWindowsEx(0x3804, 0)




    328.1528> Winlogon-Trace: ExitWindowsEx called to shut down COM processes




    328.332> Winlogon-Trace: Starting shutdown

    328.332> Winlogon-Trace: Starting user thread for Logoff, flags = 7




    328.284> Winlogon-Trace: Calling ExitWindowsEx(0x7, 0)


    If shutdown stalls then based on the log entries you should be able to identify which part of shutdown it is stuck in.




    In order to debug Winlogon you will need to first install the debugging tools for Windows (http://www.microsoft.com/whdc/devtools/debugging/default.mspx). It contains information about how to set up the debugger for Winlogon debugging. If the debugger is not set up correctly on Winlogon the system can easily get in an unusable state and the system will need to be reinstalled.


    You should debug Winlogon whenever a problem manifests itself on the Winlogon desktop where the SAS and logon prompt dialogs are displayed. When debugging Winlogon you should start by looking at the main process thread. If shutdown (or any other Winlogon activity) is hung that thread will show what happened to prevent shutdown from completing. Also look at these Winlogon flags which provide some indication of whether or not the main thread is even processing a shutdown.


    0105fe8c winlogon!g_fReadyForShutdown

    0105fdf8 winlogon!ShutdownHasBegun

    01062b3c winlogon!ShutdownInProgress

    01062b30 winlogon!ShutdownTime


    I will point out how these variables are modified.


    Shutdown Sequence of Events


    If you are debugging a shutdown issue you first need to understand the sequence of events that take place during shutdown. This will help isolate what activity may be failing.


    RPC Call


    An application, local or remote, tells Windows to shut down by calling the Win32 API InitiateSystemShutdownEx (http://msdn2.microsoft.com/en-us/library/aa376874.aspx). This API creates an RPC call over the named pipe InitShutdown. The remote connect and RPC call looks like this in a network trace.


    11:08:40.025                 CLIENT         SERVER        SMB              SMB: C; Nt Create Andx, FileName = \InitShutdown

    11:08:40.027                 CLIENT         SERVER        MSRPC        MSRPC: c/o Request: unknown Call=0x1 Opnum=0x2 Context=0x0 Hint=0x20


    A local connect would not need to go over the network, but it uses the same mechanism to make this call.


    The server side of this RPC call is handled by the function BaseInitiateShutdownEx in the Winlogon.exe process. This RPC worker performs the following actions.


    1.       Checks the privilege level of the client. If the client privilege test fails then the error status code is returned. This will typically be ERROR_ACCESS_DENIED (0x5).

    2.       Parses the shutdown command sent by the RPC client. If the command is malformed then the status error code of ERROR_INVALID_PARAMETER (0x57) is returned.

    3.       Checks the Winlogon flags ShutdownInProgress, ShutdownHasBegun, g_fReadyForShutdown, and the current state of the terminal desktop to see if we can shutdown. Winlogon cannot begin the shutdown if a shutdown is in progress or if it is not ready. Winlogon also will not start a shutdown if the force flag was not specified in the command and the desktop is locked. If the ShutdownInProgress or ShutdownHasBegun flag is set then the return value is ERROR_SHUTDOWN_IN_PROGRESS (0x45B). If the g_fReadyForShutdown is not set then the return value is ERROR_NOT_READY (0x15).


    Debugger output:

    dd winlogon!g_fReadyForShutdown l 1

    0105fe8c  00000001


    dd winlogon!ShutdownInProgress l 1

    01062b3c  00000000


    dd winlogon!ShutdownHasBegun l 1

    0105fdf8  00000000


    4.       Winlogon initializes the shutdown data including the global variable ShutdownTime. If this variable has been set then we know we’ve gotten this far.


    Debugger Output:

    dq winlogon!ShutdownTime l 1

    01062b30  01c7a859`baee0060


    .formats 01c7a859`baee0060

    Evaluate expression:

      Time:    Wed Jun  6 12:42:54.506 2007 (GMT-4)


    5.       If Winlogon has determined that it can proceed then the ShutdownInProgress flag is set. Subsequent shutdown requests from this point will fail in step 3 when it checks this flag.

    6.       Generates the shutdown audit event if auditing was enabled. Note that shutdown may fail at some point after this even though the audit log is generated.

    7.       Creates another thread to continue working on the shutdown. At this point the RPC worker thread returns to the caller.


    To this point there has been no visible indication on the server being shutdown. If the RPC worker fails for some reason then the client application will get an indication of the failure. If the RPC worker successfully hands the shutdown request to the next thread then the client application will get ERROR_SUCCESS (0) as the return code. The client application will get no indication of a failure after that point.


    Worker Thread


    The RPC worker thread hands control to the LogoffThreadProc thread. If the delay specified in the shutdown command was 0 then the ShutdownInProgress flag is cleared and the ShutdownHasBegun is set. In the Winlogon log you will see a line that starts with “Doing immediate shutdown”. Otherwise you will not see any visible indication at this point that a shutdown is occurring.


    If the delay specified in the shutdown command was greater than 0 then the countdown shutdown dialog is displayed.




    When that dialog completes the AbortShutdown flag is checked. This flag would get set as a result of a call to AbortSystemShutdown (http://msdn2.microsoft.com/en-us/library/aa376630.aspx). If it is set then the shutdown is aborted. Otherwise the ShutdownInProgress flag is cleared, the ShutdownHasBegun flag is set and if the shutdown was initiated by a system process then we shut the system down immediately at this point with no further clean up.


    After these flags are updated the ExitWindowsInProgress flag is set and we call the Win32 API ExitWindowsEx (http://msdn2.microsoft.com/en-us/library/ms893047.aspx). In the Winlogon log you will see a line that starts with “Calling ExitWindowsEx”.


    Debugger Output:

    dd winlogon!ExitWindowsInProgress l 1

    0105fd84  00000001


    The Win32 API ExitWindowsEx makes an RPC call to CSRSS.EXE. CSRSS synchronously sends a WM_QUERYENDSESSION message to all Windows applications. When an application gets this message it indicates that shutdown can continue and CSRSS then sends the WM_ENDSESSION message. After that the process is terminated. If the application indicates that it cannot be terminated then CSRSS stops processing any further applications and waits for the interactive user to close the application. The ExitWindowsEx call will fail with error ERROR_OPERATION_ABORTED (0x3E3) and the Winlogon flags are reset so that a new shutdown request can be processed.


    An application that prevents shutdown from proceeding in this manner can be seen visual since it will be the foreground window on the desktop. To confirm which application returned did this you will need to live debug CSRSS. A return code of 3 from either winsrv!ConsoleClientShutdown or winsrv!UserClientShutdown will indicate the application did this.


    Debugger Output:

    0:002> pc

    eax=00000000 ebx=7c81a3ab ecx=7ffdb000 edx=75a58ca0 esi=75a58ca0 edi=00164600

    eip=75a564de esp=0052fe40 ebp=0052fe68 iopl=0         nv up ei pl zr na po nc

    cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000246


    75a564de ff5740 call dword ptr [edi+0x40]{winsrv!UserClientShutdown (75a9db1f)} ds:0023:00164640=75a9db1f


    ; Step past the call.

    0:002> p

    eax=00000003 ebx=7c81a3ab ecx=7ffdb000 edx=75a58ca0 esi=75a58ca0 edi=00164600

    eip=75a564e1 esp=0052fe4c ebp=0052fe68 iopl=0         nv up ei pl zr na po nc

    cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000246


    75a564e1 8bf8             mov     edi,eax


    ; The first parameter is a structure that contains the process ID.

    75a564d5 ff75f4           push    dword ptr [ebp-0xc]

    75a564d8 ff750c           push    dword ptr [ebp+0xc]

    75a564db ff75f8           push    dword ptr [ebp-0x8]

    75a564de ff5740           call    dword ptr [edi+0x40]


    ; Get the pointer to this structure.

    0:002> dd ebp-8 l 1

    dd ebp-8 l 1

    0052fe60  0018a530


    ; The first DWORD is the process ID. The second DWORD is the thread ID.

    0:002> dd 0018a530 l 1

    dd 0018a530

    0018a530  0000066c


    ; Break into kernel mode so we can look at all the processes.

    0:002> .breakin


    Break instruction exception - code 80000003 (first chance)


    8081db0e cc              int     3


    ; Get the process object with that process ID.

    kd> !process 0000066c 0

    Searching for Process with Cid == 66c

    PROCESS ff62a638  SessionId: 0  Cid: 066c    Peb: 7ffdf000  ParentCid: 0108

        DirBase: 0390d000  ObjectTable: e1658e38  HandleCount:  51.

        Image: test.exe


    Console (text-based) applications are asynchronously sent a separate CTRL_SHUTDOWN_EVENT notification. This means that ExitWindowsEx will proceed no matter how the application chooses to handle this notification.


    Services.exe (and all Windows services) is a console application which receives this notification from CSRSS. Services.exe registers a control handler ScShutdownNotificationRoutine which calls ScShutdownAllServices on shutdown. This function traverses through all Windows services that are not stopped or stopping and that accept the shutdown notification and sends them the SERVICE_CONTROL_SHUTDOWN notification. Each service has 20 seconds by default to shutdown. However a service may request more time by calling SetServiceStatus with a wait hint and updated check point. It can do this so long as it continues to respond within the current timeout period. However since Services.exe received this as an asynchronous message from CSRSS.EXE it will not prevent the system from shutting down.


    After ExitWindowsEx returns control to Winlogon the ExitWindowsInProgress flag is cleared and LogoffThreadProc exits.




    The state of Winlogon is controlled by the main process thread in a function called MainLoop. As LogoffThreadProc sets the ShutdownHasBegun flag and calls ExitWindowsEx the MainLoop function picks up on this change of state and begins executing its shutdown code. Since MainLoop is responsible for interaction with the user this is the first place where the user will get visible confirmation from Winlogon that the system is shutting down.


    When MainLoop sees that the Winlogon state has changed to shutting down it takes the following actions.


    1.       Signal the shell that we are shutting down. This causes the Explorer shell to disappear.

    2.       Checks to see if there are any updates to the user’s profile.

    3.       Send out the logoff notification event.

    4.       Delete network connections.

    5.       Play the logoff sound.

    6.       Play the system exit sound.

    7.       Creates a KillComProcesses thread. This calls ExitWindowsEx and will wait up to 15 minutes for this to complete.

    8.       Save and unload the user’s profile.

    9.       Delete RAS connections.

    10.    Send out the shutdown notification event.

    11.    Stop Windows file protection.

    12.    Creates another LogoffThreadProc thread which again calls ExitWindowsEx.

    13.    Call the shutdown function in the GINA. This displays the Windows is shutting down dialog.

    14.    Wait for any remaining system processes to complete. If we are stuck here then we would need to look at System, smss.exe, or csrss.exe. One of those will be stuck in some action.

    15.    Shut down the system.


    Winlogon uses the native API NtShutdownSystem in step 15. If there is a hang after this point then you will see the main thread in Winlogon stuck in this call and the real problem is likely the result of a device driver in the System process. This call will never return.

  • Ntdebugging Blog

    Closing the Loop: CPU Spike in Winlogon.exe


    We recently dealt with an interesting issue that I would like to share, hope you enjoy. - Jason

    Issue Summary

    Customer reports that within their Citrix server farm (running on Windows Server 2003), when a user logs into or out of a session (seems more pronounced on logoff), ALL users connected to the server experience a ~5-20 second hang. The hang is described as follows:

    • Application in the session (i.e. Outlook and Word) stop accepting keyboard input. When the hang subsides, the typed characters show up all at once.
    • If applications are moved, they do not redraw
    • Cannot click the start menu
    • If the user was running performance monitor (in an attempt to diagnose), there would be a gap in the perfmon data that directly correlated to the hang duration

    Customer has found that during the timeframe of the hang, Winlogon.exe (in session 0) is showing 25% CPU usage.

    Troubleshooting & Analysis

    Where to start… to begin, given the details above, we can assume we are not experiencing a hard hang where the server is completely unresponsive. The user can still move windows and the connection to the server is still active. Keyboard input is working, but seems to be buffered during the issue. The windows not redrawing indicates the message pump for each of the affected applications is stuck waiting for something.

    In this scenario, I focused on the CPU usage for Winlogon under the premise that the other symptoms were side effects of whatever the CPU was working so hard on. On to the 25%; this is an interesting number to spike at. Generally speaking a thread has work to do, or it doesn't. If there was work to do it would normally take the CPU to 100%. So why 25%? In this scenario, each of the servers within the server farm had 4 processors. So we pegged 1 out of the 4 @ 100% resulting in task manager displaying 25% CPU utilization for the Winlogon in question.

    So now we have a CPU spike in Winlogon. Why only the Winlogon in session 0? Going back to the issue summary, the customer reported that if ANY user logs off, ALL users experience a hang, and Winlogon in session 0 spikes. First, let's talk about what winlogon does for a living.

    Sidebar: Winlogon on Windows Server 2003.

    Any time you ask what a feature is or how it works, you should begin your research with the Windows Technical Reference (try a Live search like "winlogon site:http://technet2.microsoft.com"). In this case I focused on the "How Interactive Logon Works" article.

    This article starts with:

    The Windows Server 2003 interactive logon architecture includes the following components:

    • Winlogon
    • Graphical Identification and Authentication (GINA) dynamic-link library (DLL)
    • Local Security Authority (LSA)
    • Authentication packages (NTLM and Kerberos)

    So Winlogon has something to do with Interactive logon.

    What else can we find out about the responsibilities of Winlogon

    • Registers the SAS (the secure attention sequence, a.k.a CTRL-ALT-DEL) during the boot process to keep other programs and processes from using it
    • SAS routine dispatching - When Winlogon recognizes a SAS event or the GINA delivers a SAS, Winlogon calls one of the SAS processing functions of the GINA.
    • Desktop lockdown - Winlogon helps prevent unauthorized user's from gaining access to system resources by locking down the computer desktop. At any time, Winlogon is in one of three possible states: logged on, logged off, or workstation locked
    • User profile loading - After a successful logon, Winlogon loads user profiles into the HKEY_CURRENT_USER registry key.
    • Screen saver control - Winlogon monitors keyboard and mouse activity to determine when to activate screen savers.
    • Multiple network provider support - If there are multiple network providers installed on a Windows-based system, they can be included in the authentication process and in password-updating operations

    Looking at this list of tasks performed by Winlogon, we need to try to determine which task aligns to our symptoms (hang during logon and logoff). I decided to focus on User Profiles due to the relationship between profiles and login and logoff.

    What is a User Profile? Back to Live with "user profiles site:http://technet2.microsoft.com". Out of the results, I went with the "User Profile Structure" link. The page provides the following detail:

    A user profile consists of:

    • A registry hive. The registry is a database used to store computer- and user-specific settings. Portions of the registry can be saved as files, called hives. These hives can then be reloaded for use as necessary. User profiles take advantage of the hive feature to provide roaming profile functionality. The user profile registry hive is the NTuser.dat in file form, and is mapped to the HKEY_CURRENT_USER portion of the registry when the user logs on. The NTuser.dat hive maintains the users environment preferences when the user is logged on. It stores those settings that maintain network connections, Control Panel configurations unique to the user (such as the desktop color and mouse), and application-specific settings. The majority of the settings stored in the registry are opaque to user profiles settings are owned and maintained by individual applications and operating system components.
    • A set of profile folders stored in the file system. User profile files are stored in the file system in the Documents and Settings directory, in a per user folder. The user profile folder is a container for applications and other operating system components to populate with subfolders and per-user data, such as shortcut links, desktop icons, startup applications, documents, configuration files and so forth. Windows Explorer uses the user profile folders extensively for special folders such as the users desktop, start menu and my documents folder.

    With this we can now look at the Winlogon that is spiking the CPU. My step when looking at a CPU spike for a process is to determine if the time spent is in User-mode or Kernel mode. In task manager on the Performance tab you can monitor CPU usage. If you select the View menu and chose to "Show Kernel Times" you can get additional detail showing you if the time is associated with a User-mode module or a Kernel module. In this case the Winlogon spike showed the spike to be in Kernel time. This means the application (Winlogon) asked the OS to do something and it is trying to get it done.

    My second step is to determine what user-mode request led to the spike in Kernel time. To answer this on a production system I chose to use Sysinternal's Process Explorer. I downloaded the tool and set it up so it would be able to obtain symbols from the public MS symbols server. During the repro I monitored the thread CPU time in Winlogon. Here is a screen shot of what Process Explorer looks when looking at the thread activity of an idle Winlogon.

    Figure 1 – Process Properties in Process Explorer

    When the CPU spike occurred we looked at the stack for the spiked thread (double click on the thread with the high CPU time or click the "Stack" button with the thread highlighted):



    Just to make sure, we repro'd again and looked at the call stack



    We can see here that both call stacks for the thread in question are RPC threads waiting for incoming requests. The request that came in was from userenv module running in Winlogon associated with the session of the user logging off and came into the Winlogon in session 0. The request is to unload the User Profile (highlighted above). This led to a call to RegUnloadKey call which removes a hive from the registry but does not modify the file containing the registry information.

    We now know the issue is related to unloading the user profile and specifically the registry portion of the user profile. Now we need to determine where we are spending the time in kernel mode.


    Kernrate is a tool included with the Windows 2003 resource kit. This will let us dig into the kernel mode side of what is going on. I collected the following data from kernrate during the hang condition (Summarized):

    Parsing the output, we see that 72.66% of the Kernel time was spent in the idle process. This is attributed to the 3 idle threads that are on the 3 processors not being used by the Winlogon thread. We see that the Winlogon process accounts for 20.39% of the kernel time (the CPU spike on the 4th processor). If we move into the module summary, you can see the correlated CPU times for the modules, INTELPPM (CPU driver) running on the idle processors and NTOSKRNL running on the 4th processor (this is where we will focus). In the final drill down, we see the function summary for NTOSKRNL and we can identify the function in use 82% of the time was CmpCleanUpKCBCacheTable. The Cm function prefix lets us know this is related to Configuration Manager (the Registry – see Table 2-7 from Microsoft Windows Internals 4th Edition for Commonly used Kernel Prefixes).

    What do we know? We know the issue manifests most during user logoff. We know during the logoff we are trying to unload the profile. We know that in the process of doing this we are trying to unload a registry hive. We know that leads us to spend a lot of CPU time in the Kernel doing CmpCleanUpKCBCacheTable.

    Why does this hang the machine? The registry is protected / synchronized with an ERESOURCE named CmpRegistryLock. While this is held exclusively during this cleanup function, all registry access is blocked (both read and write). This explains all of our symptoms. Applications freeze and do not redraw due to operations that need registry access being done on the GUI thread of a process. Perfmon cannot report due to its dependency on the registry.


    Now that we know the exact behavior, we could align it to a known issue that was introduced with the release of Windows Sever 2003 SP1 (applies to both SP1 and SP2)


    From the KB cause section:

    This problem occurs because of the way that Windows Server 2003 Service Pack 1 (SP1) cleans up user registry information. When a user logs off, there is a five-second delay before Windows Server 2003 SP1 flushes the user registry hive. If the terminal server experiences heavy registry activity, the cached registry information on the terminal server may increase significantly. For example, this behavior may occur when a program scans the user profile during the logoff process. When the terminal server experiences heavy registry activity, it takes Windows longer to flush the data.

    The fix applies to Windows Server 2003 with SP1 or SP2.

  • Ntdebugging Blog

    Part 3: ETW Methods of Tracing


    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.


    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



    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.


    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.


    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



    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:


    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


    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.


    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.

    image_thumb[49] image_thumb[50]



    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!


    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.


    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


    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.


    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.


    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!


    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

    Part 2 - Exploring and Decoding ETW Providers using Event Log Channels


    Introduction and Overview

    In this article we will explore a practical use for ETW tracing, and discover what ETW (Event Tracing for Windows) tracing is available for a popular Windows user-mode component, Internet Explorer. In my previous article ETW Introduction and Overview, we covered what ETW tracing is and how it could be used.

    The goal in this exercise is to learn about ETW tracing in general, how to self-discover what tracing is available in a component, and some ways you can leverage the tracing to self-troubleshoot issues. ETW logging is essentially allowing Microsoft code to speak for itself. It tells you what code ran, what that code did, and any errors produced. Also ETW logs can be used along with a more traditional toolset for troubleshooting that class of issue such as the SysInternals tools, Network Monitor, etc.

    For this article, we are using the RC Build of Windows 7. The concepts and examples should be very similar and work fine for Windows Vista.

    Getting Started “Exploring”

    First we start off by opening Internet Explorer 8 whose home page is set to the NTDebugging Blog - http://blogs.msdn.com/ntdebugging


    In order to find what Internet Explorer is logging with ETW, we list all of the registered ETW providers on a box, which includes all of the installed code on the machine (the component doesn’t need to be actively running).

    We start off by running “logman query providers” and look through the list for relevant hits. However, the results below return more than 400+ hits on Vista, and 600+ on Win7. You will probably quickly see though that searching through this large list of providers might not always be best way to go about finding which providers Internet Explorer is logging with.


    Using this list we can also filter or browse for our component. This may work just fine, however, one issue with this approach is that sometimes you may not know the particular naming convention for a process. Also, many software components use shared dlll’s to do a variety of the under the hood work. As such, you may not know what each of those pieces of software are, or how they are named.

    Here we try running a built-in cmd line tool logman ‘query providers’ and searching for “Internet”, which didn’t turn up anything on this particular search. It looks like the naming convention for Internet Explorer might be a bit different than our first search.


    While we could continue to browse the large list of providers, I have decided to use another useful method to find which providers IE uses, which is to filter all providers that a certain ProcessId uses. We start out by getting the ProcessId of Internet Explorer using two methods shown here, Task Manager and the command line tasklist filtering on iexplore.exe.



    Now that we know Internet Explorer is running with process id 6200, we can do another query with logman to find out the ETW providers.

    Internet Explorer ETW Providers

    ‘Logman query providers –pid 6200’ is used to list all of the user-mode ETW providers that Internet Explorer uses and the associated GUIDs (GUIDs are the Globally Unique ids that enable tracing for a component).

    In looking at the screenshot below, notice that a wide variety of providers are shown, and at first glance, you may wonder how some relate to Internet Explorer. As you investigate further though, all these components enable certain features within Internet Explorer, but even with tracing enabled, may not log anything unless you specifically use the part of Internet Explorer which runs that code at run-time.

    It is also important to note that Internet Explorer will also use a lot of kernel services to eventually do its work, such as NDIS. There is ETW tracing for these kernel components, but would not show up under a specific process as they are used by all processes at the kernel level. Here we see a specific component of interest that we want to follow – Microsoft-Windows-WinINet. A quick Bing search of WinINet turns up this on MSDN, which sounds relevant.

    Extracted from MSDN: The Microsoft Windows Internet (WinINet) application programming interface (API) enables applications to access standard Internet protocols, such as FTP and HTTP. For ease of use, WinINet abstracts these protocols into a high-level interface.

    So Microsoft-Windows-WinINet looks like a good component to enable tracing in.


    From using SysInternals Process Explorer you can also confirm and that WININET.dll is loaded into the address space of iexplore.exe as shown below.


    Now that we know the ETW Provider name and GUID, we will launch Computer Mgmt and turn on tracing for that component. Note that not every Provider can be decoded this way (due to architectural and security reasons), but many can, and at the very least, the log can be enabled and provided to Microsoft Support to fully decode.

    Launch Computer Management by typing ‘compmgmt.msc’ into the start search box or right clicking Manage on Computer Management.


    Enabling ETW Logging

    Once in Computer Management, Navigate to and click on Event Viewer -> Applications and Services Logs. Once there, make sure View -> Show Analytic and Debug Logs is enabled as shown below, which will provide a much greater set of logs to look at. Most logs are under Event Viewer -> Applications and Services Logs -> Microsoft -> Windows, where we will spend the majority of our time. There are generally four channels that can show up under each provider. Channels are targeted at different roles. Admin and Operational channels target IT professionals and Administrators and are enabled by default, while Analytic and Debug Channels are more in depth, and not usually enabled by default.

    The logs that show up here are XML Manifest based tracing called Windows Events. ETW tracing splits up the collection and decoding of traces into two separate steps for performance and security reasons. In the manifest based tracing first available with Vista, most components and events are defined in a XML manifest compiled along with the binary, and which are defined in a resource file language dll. Most user-mode resource dlls show up under C:\Windows\System32\en-US (for English US). The good part about manifest based tracing is that many logs are self-discoverable and customer decodable!


    Next we will browse to: Event Viewer -> Applications and Services Logs -> Microsoft -> Windows -> WinINet, right click on the Analytic channel, and choose ‘Enable Log’. Remember that we had to enable this log because Analytic and Debug logs are not enabled by default. Enabling the channel will automatically enable the ETW tracing for that component and logs will start being decoded similar to the Event Log.


    Capture and view WinINet logging for our scenario

    After enabling the log, I am going to close Internet Explorer which is running code that is now logging using ETW and navigate to the website http://blogs.msdn.com/ntdebugging.


    Now we can look at the result of our work and tracing, which decodes the tracing for us. Below, we are on the WININET_REQUEST_HEADER category, showing the GET request. Note that the tracing here is showing us proxy interaction, DNS requests and responses, cookies, TCP requests/responses, as well as HTTP requests and responses.

    Now, one might be able to get the same information using a network capturing program such as NetMon or WireShark, but the nice thing about the ETW tracing here is that is

    a) In box without having to install additional tools

    b) The aggregate view of what the WinINet component is seen from its point of view (composed of DNS, TCP, Proxy, Cookies, etc).

    This is a good example of using this tracing in combination with other troubleshooting tools (if required), which may or may not be useful depending on the scenario.


    Dumping the trace log out using other methods:

    You can use the Event Viewer GUI, or if you prefer to view the log in a text editor (or spreadsheet). You can dump the log to text or CSV format using a couple of different methods.

    The first method is using the Windows Event Log GUI to export or save the event log


    Or you can output the entire log to screen in human readable text format:


    We can also output to the screen filtering for any messages with error level using an XPath Query. We can start right away if you know the XPath Syntax for your query, or you can use the GUI to help build the query for you. Once you choose ‘Filter Current Log’ you can filter by Event Level, or a variety of other criteria.


    The XML view will show you the raw XPATH syntax needed to use wevtutil to query for only Error events.


    Now we actually run the XPath query using ‘wevtutil query-events Microsoft-Windows-WinINet/Analytic /f:Text "/q:*[System[(Level=2)]]"’


    If you prefer a more complex format containing processors, threads, etc, then you can output to a csv log file. This is useful for sorting, filtering, comparing, and doing more complex analysis on the log file entries.


    Here we use ‘tracerpt c:\windows\system32\winevet\logs\Microsoft-Windows-WinINet%4Analytic.etl –of CSV –o c:\temp\Microsoft-Windows-WinINet%4Analytic.csv’ to output to a CSV.


    Finally, you can use PowerShell v2 to dump out the log. The PowerShell scenario is interesting, because you can write powerful scripts around the event logs.


    Look at ‘get-help get-winevent –examples” for many more really cool examples about how to list and filter these logs:


    Behind the Scenes

    We also need to explore behind the scenes of what is happening when you enable the analytic channel of the WinInet provider. Part of the definition of that channel is to enable an ETW Trace Session with certain pre-defined Keywords (Flags) and Levels. Keywords usually specify functional sub-components (HTTP, COOKIES, CONNECTION, etc) while Levels control the level of detail (Error, Informational, Verbose) events are logged. This is useful to fine-tune logging, but the channels make it easy not to have to mess with these unless required.

    Under Performance -> Data Collector Sets -> Event Trace Sessions we see a new session created for us and auto-named “EventLog-Microsoft-Windows-WinINet-Analytic”. This ETW logger was automatically created for us when we enabled the WinInet Analytic channel. You can also manually create the logger, which we may cover in another blog post. If you open up the properties for this session, you'll notice our provider listed as well as all the Keywords (Any) and Level specified. The screenshot also show which Keywords/Flags or categories a provider supports.


    Once you know a provider name, you can also query for it on the command line, which is useful to get all the Keywords(Flags) and Levels a provider supports, along with the processes that are using that provider.


    For the curious, we wanted to finish this post and show you how to find what tracing is available, and its format. Here we again use the wevtutil to get full publishing event and message information.

    ‘wevtutil get-publisher Microsoft-Windows-WinInet /getevents /getmessage’


    This can be combined with another version of the same utility searching for a certain string or log – e.g. “wevtutil gp Microsoft-Windows-WinINet /ge /gm | findstr /i httpopen”


    To wrap-up, here is the overall architecture of ETW covered in a previous blog post, along with the specifics of the scenario we covered. In our scenario the MMC Event Viewer console has two roles – enabling the tracing and decoding the real-time delivery of events.


    Where to go from here?

    This was meant as a practical introduction to using and self-discovering how to use the ETW tracing that is available right now in newer Windows releases (Vista/2008 and above). There are many, many more components that use tracing – 400+ in Vista and 600+ in Win7, which you can start exploring.

    For these specific examples, it is worth noting that as far as the networking aspect is concerned, similar information might be obtained from using a packet capture utility such as NetMon. What is interesting about NetMon in Win7 is that it actually uses ETW under the hood to do most of its tracing. Here is an interesting post about Network Tracing in Windows 7 from the Netmon team.

    The use of ETW under the hood of many tools is a general trend in Windows and Microsoft software. You might notice different diagnostics and tracing tools in Windows using ETW under the hood. These tools can add value to the raw ETW tracing such as further parsing, filtering, and rich views into the data. You can mix and match these tools along with the tracing for powerful views into your Windows box or server.

    It’s also important to note that ETW tracing isn’t just for Microsoft software. Since any software running on Windows uses many services provided by the OS, there is a variety of ETW logging that is available for all software. For example, try running ‘logman query providers –pid PROCESSID_OF_FIREFOX’ on FireFox! You should find a great deal of logging similar to Internet Explorer.

    In future posts, we hope to explore other ways of using ETW tracing, and touch on some of the kernel level tracing available.



    Share this post :

  • Ntdebugging Blog

    Challenges of Debugging Optimized x64 Code


    If you have not had the luxury of debugging optimized x64 code as of yet, don’t wait much longer and fall behind the times!  Due to the x64 fastcall-like calling convention coupled with the abundance of general purpose registers, finding variable values at arbitrary points in a call stack can be very tricky indeed.

    In this article, I’d like to detail some of my favorite techniques for debugging optimized x64 code.  But before digging into these techniques, let’s first have a quick overview of the x64 calling convention.

    The x64 Calling Convention

    Those of you familiar with the fastcall calling convention on x86 platforms will recognize the similarities to the x64 calling convention.  Whereas you typically have to maintain knowledge of multiple calling conventions on x86 platforms, on x64 platforms there is currently just one.  (Of course, I’m excluding the case of no calling convention which one can achieve with __declspec(naked) or by coding in straight assembly.)

    I won’t go into all of the various nuances of the x64 calling convention, therefore I recommend you check out the following link (http://msdn.microsoft.com/en-us/library/ms794533.aspx).  But commonly, the first four parameters into a function are passed via the registers rcx, rdx, r8, and r9.  If the function accepts more than four parameters, those parameters are passed on the stack.  (Those of you familiar with the x86 fastcall calling convention where the first two parameters are passed in ecx and edx will recognize the similarities).

    To help illustrate how the x64 calling convention works, I have created some simple example code.  Although the code is contrived and far from real-world code, it demonstrates some scenarios that are likely to encounter in the real word.  The code is shown below.

    #include <stdlib.h>

    #include <stdio.h>

    #include <windows.h>



    FunctionWith4Params( int param1, int param2, int param3,

                         int param4 )


        size_t lotsOfLocalVariables1 = rand();

        size_t lotsOfLocalVariables2 = rand();

        size_t lotsOfLocalVariables3 = rand();

        size_t lotsOfLocalVariables4 = rand();

        size_t lotsOfLocalVariables5 = rand();

        size_t lotsOfLocalVariables6 = rand();


        printf( "Entering FunctionWith4Params( %X, %X, %X, %X )\n",

                param1, param2, param3, param4 );

        printf( "Local variables: %X, %X, %X, %X, %X, %X \n",

                lotsOfLocalVariables1, lotsOfLocalVariables2,

                lotsOfLocalVariables3, lotsOfLocalVariables4,

                lotsOfLocalVariables5, lotsOfLocalVariables6 );




    FunctionWith5Params( int param1, int param2, int param3,

                         int param4, int param5 )


        FunctionWith4Params( param5, param4, param3, param2 );

        FunctionWith4Params( rand(), rand(), rand(), rand() );




    FunctionWith6Params( int param1, int param2, int param3,

                         int param4, int param5, int param6 )


        size_t someLocalVariable1 = rand();

        size_t someLocalVariable2 = rand();

        printf( "Entering %s( %X, %X, %X, %X, %X, %X )\n",


                param1, param2, param3, param4, param5, param6 );

        FunctionWith5Params( rand(), rand(), rand(),

                             param1, rand() );

        printf( "someLocalVariable1 = %X, someLocalVariable2 = %X\n",

                someLocalVariable1, someLocalVariable2 );



    main( int /*argc*/, TCHAR** /*argv*/ )


        // I use the rand() function throughout this code to keep

        // the compiler from optimizing too much.  If I had used

        // constant values, the compiler would have optimized all

        // of these away.

        int params[] = { rand(), rand(), rand(),

                         rand(), rand(), rand() };

        FunctionWith6Params( params[0], params[1], params[2],

                             params[3], params[4], params[5] );

        return 0;



    Cut and paste this code into a cpp file (such as example.cpp).  I used the Windows SDK (specifically the Windows SDK CMD Shell) to compile this code as C++ code by using the following command line:

    cl /EHa /Zi /Od /favor:INTEL64 example.cpp /link /debug

    Notice the /Od switch.  This disables all optimizations.  Later on, I’ll enable maximum optimization and that’s when the fun begins!

    Once you have the executable module built (mine is named example.exe), then you can fire it up in the debugger as follows:

    windbg -Q -c "bu example!main;g;" example.exe

    The command above will launch the application in windbg, set a breakpoint on the main() routine, and then go to that breakpoint.

    Now, let’s have a look at a diagram of what the stack looks like when FunctionWith6Params() gets called.  The diagram shown below illustrates the stack when the instruction pointer is at the beginning of the code for FunctionWith6Params() but before the prolog code has executed:


    Notice that the caller, in this case main(), allocated enough space on the stack for all six parameters to FunctionWith6Params() even though the first four parameters are passed in via registers.  The extra space on the stack is commonly referred to as the “home space” for the register parameters.  In the previous diagram, I have shown those slots filled with xxxxxxxx to indicate that the values within there are virtually random at this point.  That’s because the caller, main(), does not initialize these slots.  The called function, at its discretion, may store the first four parameters in this space for safe keeping.  This is exactly what happens in non-optimized builds and is a huge debugging convenience since you can easily find the contents of the first four parameters on the stack if you need to.  Additionally, windbg stack commands such as kb and kv which show these first few parameters will report true results.

    With all of that said, here is what the stack looks like after the prolog code in FunctionWith6Params() executes:


    The prolog assembly code for FunctionWith6Params() is shown below:

    0:000> uf .

    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 28]:

       41 00000001`40015900 mov     dword ptr [rsp+20h],r9d
       41 00000001`40015905 mov     dword ptr [rsp+18h],r8d
       41 00000001`4001590a mov     dword ptr [rsp+10h],edx
       41 00000001`4001590e mov     dword ptr [rsp+8],ecx
       41 00000001`40015912 push    rbx
       41 00000001`40015913 push    rsi
       41 00000001`40015914 push    rdi
       41 00000001`40015915 sub     rsp,50h

    You can see that the first four instructions save the first four parameters on the stack in the home space allocated by main().  Then, the prolog code saves any non-volatile registers that FunctionWith6Params() plans to use during its execution.  The saved registers’ states are restored in the function epilog code prior to returning to the caller.  Finally the prolog code reserves some space on the stack, in this case, for 0x50 bytes.

    What is this space reserved on the top of the stack for?  First, space is created for any local variables.  In this case, FunctionWith6Params() has two.  However, those two local variables only account for 0x10 bytes.  What’s the deal with the rest of the space created on the top of the stack?

    On the x64 platform, when code prepares the stack for calling another function, it does not use push instructions to put the parameters on the stack as is commonly the case in x86 code.  Instead, the stack pointer typically remains fixed for a particular function.  The compiler looks at all of the functions the code in the current function calls, it finds the one with the maximum number of parameters, and then creates enough space on the stack to accommodate those parameters.  In this example, FunctionWith6Params() calls printf() passing it 8 parameters.  Since that is the called function with the maximum number of parameters, the compiler creates 8 slots on the stack.  The top four slots on the stack will then be the home space used by any functions FunctionWith6Params() calls.

    A handy side effect of the x64 calling convention is that once you are inside the bracket of the prolog and epilog of a function, the stack pointer does not change while the instruction pointer is in that function.  This eliminates the need for a base pointer which is common in x86 calling conventions.  When the code in FunctionWith6Params() prepares to call a child function, it simply puts the first four parameters into the required registers and, if there are more than 4 parameters, it uses mov instructions to place the remaining parameters in the allocated stack space but making sure to skip the first four parameter slots on the stack.

    Debugging Optimized x64 code (The Nightmare Begins)

    Why is debugging x64 optimized code so tricky?  Well, remember that home space that the caller creates on the stack for the callee to save the first four parameters?  It turns out that the calling convention does not require the callee to use that space!  And you can certainly bet that optimized x64 code will not use that space unless it is necessary and convenient for its optimization purposes.  Moreover, when optimized code does use the home space, it could use it to store non-volatile registers rather than the first four parameters to the function.

    Go ahead and recompile the example code using the following command line:

    cl /EHa /Zi /Ox /favor:INTEL64 example.cpp /link /debug

    Notice the use of the /Ox switch.  This turns on maximum optimization.  Debug symbols are still turned on so we can debug the optimized code easily.  Always build your release product with debug information turned on so you can debug your release builds!

    Let’s look at how the prolog assembly code for FunctionWith6Params() has changed:

       41 00000001`400158e0 mov     qword ptr [rsp+8],rbx
       41 00000001`400158e5 mov     qword ptr [rsp+10h],rbp
       41 00000001`400158ea mov     qword ptr [rsp+18h],rsi
       41 00000001`400158ef push    rdi
       41 00000001`400158f0 push    r12
       41 00000001`400158f2 push    r13
       41 00000001`400158f4 sub     rsp,40h
       41 00000001`400158f8 mov     ebx,r9d
       41 00000001`400158fb mov     edi,r8d
       41 00000001`400158fe mov     esi,edx
       41 00000001`40015900 mov     r12d,ecx

    The optimized code is significantly different!  Let’s itemize the changes below:

    ·         The function uses the home space on the stack, however, it does not store the first four parameters there.  Instead it uses the space to store some non-volatile registers it must restore later in the epilog code.  This optimized code is going to make use of more processor registers, therefore it must save more of the non-volatile registers.

    ·         It still pushes three non-volatile registers onto the stack for safe keeping along with the other three it stored in the home space.

    ·         It then creates space on the stack.  However, it’s less space than in the non-optimized code, and is only 0x40 bytes.  That’s because the optimized code uses registers to represent the local variables someLocalVariable1 and someLocalVariable2.  Therefore, it only has to create space for the 8 slots needed to call the function with the maximum number of parameters, printf().

    ·         It then stores the first four parameters into non-volatile registers rather than in the home space. (Don’t count on this behavior.  An optimized function may make no copies of the contents of rcx, rdx, r8, and r9.  It all depends on the structure of the code)

    Now step through FunctionWith6Params() to the source line just after the first printf() call.  The output generated from the printf() call on my machine is as follows:

    Entering FunctionWith6Params( 29, 4823, 18BE, 6784, 4AE1, 3D6C )

    A common version of the stack command in windbg is kb, which also displays the first few parameters to each function in the frame.  In reality, it is displaying the first few positions of the stack.  The output for the kb command is as follows:

    0:000> kb
    RetAddr           : Args to Child                                                           : Call Site
    00000001`4001593b : 00000000`00004ae1 00000000`00004823 00000000`000018be 00000000`007e3570 : example!FunctionWith6Params+0x6a [c:\temp\blog_entry\sample_code\example.cpp @ 37]
    00000001`40001667 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000001 : example!main+0x5b [c:\temp\blog_entry\sample_code\example.cpp @ 57]
    00000000`76d7495d : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : example!__tmainCRTStartup+0x15b
    00000000`76f78791 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd
    00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d

    Notice that not all of the first four parameters of FunctionWith6Params() match what is shown by the kb command!  Of course, this is a side effect of the optimization.  You simply cannot trust the output displayed by kb and kv in optimized code.  This is the biggest reason why optimized x64 code is so difficult to debug.  Trust me when I say that it’s just pure luck that the second and third slots in the kb output above match the actual parameter values to FunctionWith6Params().  It’s because FunctionWith6Params() stores non-volatile registers in those slots and it just so happens that main() put those values in those non-volatile registers prior to calling FunctionWith6Params().

    Parameter Sleuthing -- Technique 1 (Down the Call Graph)

    Now, let’s look at some techniques for finding elusive function parameters to functions in the call stack while running x64 code.  I have placed a DebugBreak() call in FunctionWith4Params() to illustrate.  Go ahead and let the code run in windbg until it hits this breakpoint.  Now, imagine what you are looking at is actually not a live debugging scenario but rather a dump file from a customer of yours and this is the point where your application has crashed.  So, you take a look at the stack and it looks like the following:

    0:000> kL
    Child-SP          RetAddr           Call Site
    00000000`0012fdc8 00000001`40015816 ntdll!DbgBreakPoint
    00000000`0012fdd0 00000001`400158a0 example!FunctionWith4Params+0x66
    00000000`0012fe50 00000001`40015977 example!FunctionWith5Params+0x20
    00000000`0012fe80 00000001`40015a0b example!FunctionWith6Params+0x97
    00000000`0012fee0 00000001`4000168b example!main+0x5b
    00000000`0012ff20 00000000`7733495d example!__tmainCRTStartup+0x15b
    00000000`0012ff60 00000000`77538791 kernel32!BaseThreadInitThunk+0xd
    00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

    Now, let’s say that in order for you to figure out what went wrong, you need to know the first parameter to FunctionWith6Params().  Assume you have not seen the first parameter in the console output. No fair cheating!

    The first technique I would like to illustrate involves digging downward into the call graph  to find out what has happened to the contents of rcx (the first parameter) after entering FunctionWith6Params().  In this case, since the parameters are 32bit integers, we’ll be attempting to follow the contents of ecx, which is the lower half of rcx.

    Let’s start by looking at the assembly code within FunctionWith6Params() starting from the beginning up to the call into FunctionWith5Params()::

    0:000> u example!FunctionWith6Params example!FunctionWith6Params+0x97
    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 41]:
    00000001`400158e0 mov     qword ptr [rsp+8],rbx
    00000001`400158e5 mov     qword ptr [rsp+10h],rbp
    00000001`400158ea mov     qword ptr [rsp+18h],rsi
    00000001`400158ef push    rdi
    00000001`400158f0 push    r12
    00000001`400158f2 push    r13
    00000001`400158f4 sub     rsp,40h
    00000001`400158f8 mov     ebx,r9d
    00000001`400158fb mov     edi,r8d
    00000001`400158fe mov     esi,edx
    00000001`40015900 mov     r12d,ecx
    00000001`40015903 call    example!rand (00000001`4000148c)
    00000001`40015908 movsxd  r13,eax
    00000001`4001590b call    example!rand (00000001`4000148c)
    00000001`40015910 lea     rdx,[example!`string'+0x68 (00000001`40020d40)]
    00000001`40015917 movsxd  rbp,eax
    00000001`4001591a mov     eax,dword ptr [rsp+88h]
    00000001`40015921 lea     rcx,[example!`string'+0x80 (00000001`40020d58)]
    00000001`40015928 mov     dword ptr [rsp+38h],eax
    00000001`4001592c mov     eax,dword ptr [rsp+80h]
    00000001`40015933 mov     r9d,esi
    00000001`40015936 mov     dword ptr [rsp+30h],eax
    00000001`4001593a mov     r8d,r12d
    00000001`4001593d mov     dword ptr [rsp+28h],ebx
    00000001`40015941 mov     dword ptr [rsp+20h],edi
    00000001`40015945 call    example!printf (00000001`400012bc)
    00000001`4001594a call    example!rand (00000001`4000148c)
    00000001`4001594f mov     edi,eax
    00000001`40015951 call    example!rand (00000001`4000148c)
    00000001`40015956 mov     esi,eax
    00000001`40015958 call    example!rand (00000001`4000148c)
    00000001`4001595d mov     ebx,eax
    00000001`4001595f call    example!rand (00000001`4000148c)
    00000001`40015964 mov     r9d,r12d
    00000001`40015967 mov     r8d,esi
    00000001`4001596a mov     edx,ebx
    00000001`4001596c mov     ecx,eax
    00000001`4001596e mov     dword ptr [rsp+20h],edi
    00000001`40015972 call    example!ILT+5(?FunctionWith5ParamsYAXHHHHHZ) (00000001`4000100a)

    FunctionWith6Params() copies ecx into r12d to preserve it for later use since the contents must be passed to multiple functions within the body of FunctionWith6Params().  Notice at the point where FunctionWith5Params() is called, the contents of ecx have been copied into both r12d and r9d, however, r9d is volatile so we must be careful with it since it could get overwritten prior to the next function call when FunctionWith5Params() calls FunctionWith4Params().  Armed with this information, let’s dig into the assembly code for FunctionWith5Params() that has executed up to this point:

    0:000> u example!FunctionWith5Params example!FunctionWith5Params+0x20
    example!FunctionWith5Params [c:\temp\blog_entry\sample_code\example.cpp @ 32]:
    00000001`40015880 mov     qword ptr [rsp+8],rbx
    00000001`40015885 mov     qword ptr [rsp+10h],rsi
    00000001`4001588a push    rdi
    00000001`4001588b sub     rsp,20h
    00000001`4001588f mov     ecx,dword ptr [rsp+50h]
    00000001`40015893 mov     eax,r9d
    00000001`40015896 mov     r9d,edx
    00000001`40015899 mov     edx,eax
    00000001`4001589b call    example!ILT+10(?FunctionWith4ParamsYAXHHHHZ) (00000001`4000100f)

    At the point where FunctionWith4Params() is called, the value we are after is now in eax, edx, and r12d.  Again, be careful with eax and edx as they are volatile.  However, since FunctionWith5Params() did not touch r12d, the contents of the parameter we are still after are still in r12d

    Now, let’s look at the code in FunctionWith4Params() that has executed so far:

    0:000> u example!FunctionWith4Params example!FunctionWith4Params+0x66
    example!FunctionWith4Params [c:\temp\blog_entry\sample_code\example.cpp @ 9]:
    00000001`400157b0 48895c2408      mov     qword ptr [rsp+8],rbx
    00000001`400157b5 48896c2410      mov     qword ptr [rsp+10h],rbp
    00000001`400157ba 4889742418      mov     qword ptr [rsp+18h],rsi
    00000001`400157bf 57              push    rdi
    00000001`400157c0 4154            push    r12
    00000001`400157c2 4155            push    r13
    00000001`400157c4 4156            push    r14
    00000001`400157c6 4157            push    r15
    00000001`400157c8 4883ec50        sub     rsp,50h
    00000001`400157cc 458be1          mov     r12d,r9d
    00000001`400157cf 458be8          mov     r13d,r8d
    00000001`400157d2 448bf2          mov     r14d,edx
    00000001`400157d5 448bf9          mov     r15d,ecx
    00000001`400157d8 e8afbcfeff      call    example!rand (00000001`4000148c)
    00000001`400157dd 4898            cdqe
    00000001`400157df 4889442448      mov     qword ptr [rsp+48h],rax
    00000001`400157e4 e8a3bcfeff      call    example!rand (00000001`4000148c)
    00000001`400157e9 4898            cdqe
    00000001`400157eb 4889442440      mov     qword ptr [rsp+40h],rax
    00000001`400157f0 e897bcfeff      call    example!rand (00000001`4000148c)
    00000001`400157f5 4863e8          movsxd  rbp,eax
    00000001`400157f8 e88fbcfeff      call    example!rand (00000001`4000148c)
    00000001`400157fd 4863f0          movsxd  rsi,eax
    00000001`40015800 e887bcfeff      call    example!rand (00000001`4000148c)
    00000001`40015805 4863f8          movsxd  rdi,eax
    00000001`40015808 e87fbcfeff      call    example!rand (00000001`4000148c)
    00000001`4001580d 4863d8          movsxd  rbx,eax
    00000001`40015810 ff15a24b0100    call    qword ptr [example!_imp_DebugBreak (00000001`4002a3b8)]

    We just found what we are looking for!  The red highlighted line shows r12 being saved on the stack because FunctionWith4Params() wants to reuse r12.  Since r12 is a non-volatile register, it must save the contents somewhere so it can restore the contents before the function exits.  All we have to do is locate that slot on the stack, and assuming that the stack has not been corrupted, we’ll have our prize.

    One technique for finding the slot is to start with the Child-SP value associated with the FunctionWith4Params() frame in the stack dump shown previously, which is 00000000`0012fdd0 in my build.  Using that value, let’s dump the stack content using the dps command:

    0:000> dps 00000000`0012fdd0 L10
    00000000`0012fdd0  00000001`00000001
    00000000`0012fdd8  00000001`40024040 example!_iob+0x30
    00000000`0012fde0  00000000`00000000
    00000000`0012fde8  00000001`40002f9e example!_getptd_noexit+0x76
    00000000`0012fdf0  00000000`00261310
    00000000`0012fdf8  00000001`40001a92 example!_unlock_file2+0x16
    00000000`0012fe00  00000000`00000001
    00000000`0012fe08  00000000`00004823
    00000000`0012fe10  00000000`000041bb
    00000000`0012fe18  00000000`00005af1
    00000000`0012fe20  00000000`00000000
    00000000`0012fe28  00000000`00000000
    00000000`0012fe30  00000000`00002cd6
    00000000`0012fe38  00000000`00000029
    00000000`0012fe40  00000000`00006952
    00000000`0012fe48  00000001`400158a0 example!FunctionWith5Params+0x20 [c:\temp\blog_entry\sample_code\example.cpp @ 34]

    I have highlighted the position that rsp points to when we enter FunctionWith4Params() in red.  Based on the prolog code shown for FunctionWith4Params() above, we can find the slot where our prize is stored.  I have highlighted it in green above and you can see the value on my machine is 0x29, which matches the value printf() sent to the console.  Additionally, I highlighted r14d in green in the assembly code for FunctionWith4Params() to indicate where the contents of edx (the second parameter) were copied to.  Since FunctionWith4Params() is virtually the top function on the stack (due to the fact that DebugBreak() takes no parameters), then r14d should also contain the value we are after.  Dumping the contents of r14 proves this as shown below:

    0:000> r r14

    To sum up, when you are chasing register-passed parameter values down through a call graph, look for places where the value is copied into.  Specifically, if the value is copied into a non-volatile register, that can be a good thing.  If a downstream function wants to reuse that non-volatile register, it must first save the contents (usually on the stack) so it can restore it when it is done.  If you’re not that lucky, you may be able to trace a register it was copied into which has not been changed at the breakpoint.  Both conditions were shown above.

    Parameter Sleuthing -- Technique 2 (Up the Call Graph)

    The second technique I would like to demonstrate is very similar to the first technique except that we walk the stack/call-graph in the opposite direction as before, that is, up the call graph.  Unfortunately, none of these techniques are fool proof and guaranteed to bear fruit.  So, it’s nice to have multiple techniques to employ even though all of them may strike out.

    We know that when FunctionWith6Params() gets called, ecx contains the value we are after.  Therefore, if we look at the code for main(), maybe we can find the source from which the ecx register was filled prior to the function call.  Let’s have a look as the assembly code in main():

    0:000> u example!main example!main+0x5b
    example!main [c:\temp\blog_entry\sample_code\example.cpp @ 58]:
    00000001`400159b0 48895c2408      mov     qword ptr [rsp+8],rbx
    00000001`400159b5 48896c2410      mov     qword ptr [rsp+10h],rbp
    00000001`400159ba 4889742418      mov     qword ptr [rsp+18h],rsi
    00000001`400159bf 48897c2420      mov     qword ptr [rsp+20h],rdi
    00000001`400159c4 4154            push    r12
    00000001`400159c6 4883ec30        sub     rsp,30h
    00000001`400159ca e8bdbafeff      call    example!rand (00000001`4000148c)
    00000001`400159cf 448be0          mov     r12d,eax
    00000001`400159d2 e8b5bafeff      call    example!rand (00000001`4000148c)
    00000001`400159d7 8be8            mov     ebp,eax
    00000001`400159d9 e8aebafeff      call    example!rand (00000001`4000148c)
    00000001`400159de 8bf0            mov     esi,eax
    00000001`400159e0 e8a7bafeff      call    example!rand (00000001`4000148c)
    00000001`400159e5 8bf8            mov     edi,eax
    00000001`400159e7 e8a0bafeff      call    example!rand (00000001`4000148c)
    00000001`400159ec 8bd8            mov     ebx,eax
    00000001`400159ee e899bafeff      call    example!rand (00000001`4000148c)
    00000001`400159f3 448bcf          mov     r9d,edi
    00000001`400159f6 89442428        mov     dword ptr [rsp+28h],eax
    00000001`400159fa 448bc6          mov     r8d,esi
    00000001`400159fd 8bd5            mov     edx,ebp
    00000001`400159ff 418bcc          mov     ecx,r12d
    00000001`40015a02 895c2420        mov     dword ptr [rsp+20h],ebx
    00000001`40015a06 e8fab5feff      call    example!ILT+0(?FunctionWith6ParamsYAXHHHHHHZ) (00000001`40001005)

    We see that ecx was copied from the contents of r12d.  This is helpful since r12d is a non-volatile register, and if it is reused by a function further down the call stack, it must be preserved and that preservation usually means putting a copy on the stack.  It would have been nice if ecx were filled with a value from the stack, at which point we would be virtually done.  But in this case, we just need to start our journey back downwards again.

    We don’t have to look very far.  Let’s have another look at the prolog code for FunctionWith6Params():

    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 41]:
       41 00000001`400158e0 mov     qword ptr [rsp+8],rbx
       41 00000001`400158e5 mov     qword ptr [rsp+10h],rbp
       41 00000001`400158ea mov     qword ptr [rsp+18h],rsi
       41 00000001`400158ef push    rdi
       41 00000001`400158f0 push    r12
       41 00000001`400158f2 push    r13
       41 00000001`400158f4 sub     rsp,40h
       41 00000001`400158f8 mov     ebx,r9d
       41 00000001`400158fb mov     edi,r8d
       41 00000001`400158fe mov     esi,edx
       41 00000001`40015900 mov     r12d,ecx

    r12 is reused in FunctionWith6Params(), which means that our prize will be on the stack.  Let’s start by looking at the Child-SP for this frame which is at 00000000`0012fe80 by using the dps command:

    0:000> dps 00000000`0012fe80 L10
    00000000`0012fe80  00000000`00001649
    00000000`0012fe88  00000000`00005f90
    00000000`0012fe90  00000000`00000029
    00000000`0012fe98  00000000`00004823
    00000000`0012fea0  00000000`00006952
    00000000`0012fea8  00000001`00006784
    00000000`0012feb0  00000000`00004ae1
    00000000`0012feb8  00000001`00003d6c
    00000000`0012fec0  00000000`00000000
    00000000`0012fec8  00000000`00000029
    00000000`0012fed0  00000000`00006784
    00000000`0012fed8  00000001`4000128b example!main+0x5b [c:\temp\blog_entry\sample_code\example.cpp @ 72]

    I have highlighted in red the slot rsp points to when we enter FunctionWith6Params().  At this point, it is a simple matter to walk the assembly code and find the slot where the value is stored.  I have highlighted it in green above.

    Parameter Sleuthing -- Technique 3 (Inspecting Dead Space)

    The final technique I would like to demonstrate involves a little more trickery and involves looking at “dead” or previously used slots on the stack that are not used by the current function call.  To demonstrate, let’s say that after the DebugBreak() is hit, we need to know what the contents of param4 that were passed to FunctionWith6Params().  Let’s have another look at the assembly that has executed for FunctionWith6Params() and this time, let’s follow r9d, the fourth parameter:

    0:000> u example!FunctionWith6Params example!FunctionWith6Params+0x97
    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 41]:
    00000001`400158e0 mov     qword ptr [rsp+8],rbx
    00000001`400158e5 mov     qword ptr [rsp+10h],rbp
    00000001`400158ea mov     qword ptr [rsp+18h],rsi
    00000001`400158ef push    rdi
    00000001`400158f0 push    r12
    00000001`400158f2 push    r13
    00000001`400158f4 sub     rsp,40h
    00000001`400158f8 mov     ebx,r9d
    00000001`400158fb mov     edi,r8d
    00000001`400158fe mov     esi,edx
    00000001`40015900 mov     r12d,ecx
    00000001`40015903 call    example!rand (00000001`4000148c)
    00000001`40015908 movsxd  r13,eax
    00000001`4001590b call    example!rand (00000001`4000148c)
    00000001`40015910 lea     rdx,[example!`string'+0x68 (00000001`40020d40)]
    00000001`40015917 movsxd  rbp,eax
    00000001`4001591a mov     eax,dword ptr [rsp+88h]
    00000001`40015921 lea     rcx,[example!`string'+0x80 (00000001`40020d58)]
    00000001`40015928 mov     dword ptr [rsp+38h],eax
    00000001`4001592c mov     eax,dword ptr [rsp+80h]
    00000001`40015933 mov     r9d,esi
    00000001`40015936 mov     dword ptr [rsp+30h],eax
    00000001`4001593a mov     r8d,r12d
    00000001`4001593d mov     dword ptr [rsp+28h],ebx
    00000001`40015941 mov     dword ptr [rsp+20h],edi
    00000001`40015945 call    example!printf (00000001`400012bc)
    00000001`4001594a call    example!rand (00000001`4000148c)
    00000001`4001594f mov     edi,eax
    00000001`40015951 call    example!rand (00000001`4000148c)
    00000001`40015956 mov     esi,eax
    00000001`40015958 call    example!rand (00000001`4000148c)
    00000001`4001595d mov     ebx,eax
    00000001`4001595f call    example!rand (00000001`4000148c)
    00000001`40015964 mov     r9d,r12d
    00000001`40015967 mov     r8d,esi
    00000001`4001596a mov     edx,ebx
    00000001`4001596c mov     ecx,eax
    00000001`4001596e mov     dword ptr [rsp+20h],edi
    00000001`40015972 call    example!ILT+5(?FunctionWith5ParamsYAXHHHHHZ) (00000001`4000100a)

    Notice that r9d is first moved into ebx.  But also, notice that it copied the contents into a slot on the stack at rsp+0x28.  What is this slot?  It’s the sixth parameter to the following printf() call.  Remember that the compiler looks at all of the functions the code calls and finds the function with the maximum number of parameters and then allocates enough space for that function.  As the code prepares to call printf(), it is moving the value we are after into the sixth parameter slot in that reserved stack space.  But what use is this information?

    If you examine FunctionWith6Params(), you see that every function called after printf() takes less than six parameters.  Specifically, the call to FunctionWith5Params() only uses five of those slots and just leaves the remaining three with junk in them.  This junk is actually our treasure!  From examining the code, it’s guaranteed that nobody has overwritten the slot represented by rsp+28.

    To find this slot, let’s again start by getting the Child-SP value for the frame we’re talking about as shown below:

    0:000> kL
    Child-SP          RetAddr           Call Site
    00000000`0012fdc8 00000001`40015816 ntdll!DbgBreakPoint
    00000000`0012fdd0 00000001`400158a0 example!FunctionWith4Params+0x66
    00000000`0012fe50 00000001`40015977 example!FunctionWith5Params+0x20
    00000000`0012fe80 00000001`40015a0b example!FunctionWith6Params+0x97
    00000000`0012fee0 00000001`4000168b example!main+0x5b
    00000000`0012ff20 00000000`7733495d example!__tmainCRTStartup+0x15b
    00000000`0012ff60 00000000`77538791 kernel32!BaseThreadInitThunk+0xd
    00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

    We can then take the highlighted value above and use the same offset in the code to find our value:

    0:000> dd 000000000012fe80+28 L1
    00000000`0012fea8  00006784

    As expected, the “dead” slot on the stack contains the value we are after.  You can compare the value to the output shown on the console to verify.

    A Non-volatile Register Shortcut

    Now that I have shown you the theory behind finding these elusive values passed around in registers, let me show you a shortcut that will make life a little bit easier.  The shortcut relies upon the /r option of the .frame command.  When using .frame /r, the debugger has the smarts to track non-volatile registers.  But as with any technique, always have multiple tools in your pocket in case you need to use all of them to verify a result.

    To demonstrate, let’s consider Technique 2 described previously where we look up the call graph and we want to know what r12 was prior to main() calling FunctionWith6Params().  Go ahead and re-launch the application in windbg and let it run until it hits the DebugBreak().  Now, let’s take a look at the stack including the frame numbers:

    0:000> knL
     # Child-SP          RetAddr           Call Site
    00 00000000`0012fdc8 00000001`40015816 ntdll!DbgBreakPoint
    01 00000000`0012fdd0 00000001`400158a0 example!FunctionWith4Params+0x66
    02 00000000`0012fe50 00000001`40015977 example!FunctionWith5Params+0x20
    03 00000000`0012fe80 00000001`40015a0b example!FunctionWith6Params+0x97
    04 00000000`0012fee0 00000001`4000168b example!main+0x5b
    05 00000000`0012ff20 00000000`7748495d example!__tmainCRTStartup+0x15b
    06 00000000`0012ff60 00000000`775b8791 kernel32!BaseThreadInitThunk+0xd
    07 00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

    Based on our previous analysis of the assembly in main(), we know that the first parameter to FunctionWith6Params() was also stored in the non-volatile register r12 in main() prior to calling FunctionWith6Params().  Now, check out what we get when we use the .frame /r command to set the current frame to 4.

    0:000> .frame /r 4
    04 00000000`0012fee0 00000001`4000168b example!main+0x5b [c:\temp\blog_entry\sample_code\example.cpp @ 70]
    rax=0000000000002ea6 rbx=0000000000004ae1 rcx=0000000000002ea6
    rdx=0000000000145460 rsi=00000000000018be rdi=0000000000006784
    rip=0000000140015a0b rsp=000000000012fee0 rbp=0000000000004823
     r8=000007fffffdc000  r9=0000000000001649 r10=0000000000000000
    r11=0000000000000246 r12=0000000000000029 r13=0000000000000000
    r14=0000000000000000 r15=0000000000000000
    iopl=0         nv up ei pl nz na pe nc
    cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
    00000001`40015a0b 488b5c2440      mov     rbx,qword ptr [rsp+40h] ss:00000000`0012ff20=0000000000000000

    As you can see, .frame /r shows the register contents as they were in main() prior to calling FunctionWith6Params().  Beware!  You can only trust the non-volatile registers when using this command!  Be sure to check out the following link to see which registers are considered volatile: Register Usage for x64 64-Bit.

    .frame /r can spare you the time spent manually digging around on the stack to find saved volatile registers.  In my experiments, .frame /r even works where there is no symbol information available.  However, it never hurts to know how to do it manually in case you’re faced with a situation where .frame /r breaks down.


    The x64 calling convention and the abundance of general purpose registers in the processor bring many opportunities for optimization to the table.  However, when all of those optimizations are in play, they can certainly make debugging difficult.  After giving a brief overview of the x64 calling convention, I demonstrated three techniques one can use to find parameter values to various functions in the call stack.  I also showed you a shortcut you can use to see non-volatile registers for a particular frame in the call stack.  I hope you find these techniques useful in your debugging adventures.  Additionally, I urge you to become more familiar with all of the nuances of the x64 calling convention.


  • Ntdebugging Blog

    How Windows Starts Up (Part the second)


    Howdy folks, David here again with part two of How Windows Starts Up.  Today we’ll be covering the Boot Loader Phase.  Let’s take a moment to recap where we are at this point.  So far, the computer has completed POST, executed the MBR code, located the active partition, executed the Boot Sector code in that partition, found NTLDR and loaded it into memory.  So what happens next?  During this phase, we’ll be discussing the following files located in the root of your system volume:  NTLDR, ntdetect.com and boot.ini.


    The Boot Loader Phase begins when NTLDR executes:


    1.    NTLDR switches the processor from real mode to 32-bit flat memory mode.

    How does it do this you ask?  NTLDR contains two parts – a 16-bit component which handles switching the processor to Protected Mode and a 32-bit component which handles everything else. 


    When NTLDR first begins execution, the processor is in an x86-operating mode called Real-Mode.  In Real-Mode, no virtual to physical translation of memory addresses occurs, which means that all memory addresses use the 16-bit Segment:Offset format, and only the first 1MB of the computer's physical memory is accessible.  However, we don’t have to concern ourselves with this too much because the first action NTLDR takes is to switch the CPU to Protected-Mode. 


    *Trivia Alert*  before we enter Protected-Mode, we enable the A20 Line – you IBM guys know what I’m talking about… 


    Still no virtual-to-physical translation occurs at this point in the boot process, but a full 32 bits of memory addressing becomes accessible, and now NTLDR can access up to 4GB of physical memory. 


    2.    NTLDR creates enough page tables to make memory below 16MB accessible with paging turned on.  This number has been increased with Windows Server 2003. 


    3.    NTLDR enables paging.  “Protected-Mode with Paging Enabled” is the mode in which Windows executes during normal operation.


    4.    NTLDR then starts the FAT and NTFS mini file system drivers contained within its own code.  Unlike the Boot Sector's file system code, NTLDR's code is sophisticated enough to read subdirectories.


    Note:   All disk access from this point until the Kernel Phase begins uses BIOS Interrupt 13h, Extended Interrupt 13h or NTBOOTDD.SYS


    5.    NTLDR locates and parses Hiberfil.sys to determine if it contains a valid hibernator file.  If a valid hibernator file is found, then that file is loaded into memory and execution continues from the point the computer was placed into hibernation.


    Hibernation files are interesting.  The file either contains a full memory image, or it contains a pointer (ARC path) to the boot partition of the last operating system that entered hibernation.  That boot partition will contain another Hiberfil.sys file, which contains a full memory image of the hibernating operating system.  If the Hiberfil.sys file is a pointer, the file will contain an ARC path using one of the following syntaxes:


                             - linkmulti()disk()rdisk()partition()

                             - linksignature()disk()rdisk()partition()

                             - linkscsi()disk()rdisk()partition()


    6.    If Hiberfil.sys is not found, NTLDR parses the Boot.ini file.  If the Boot.ini contains a reference to more than one operating system or boot option, then the boot loader screen is displayed. 


    This is a sample of a default Boot.ini file from a Windows 2000 Server-based computer:


    [boot loader]



    [operating systems]

    multi(0)disk(0)rdisk(0)partition(1)\WINNT="Windows 2000 Server" /fastdetect


    Let’s talk a bit about what’s in the Boot.ini file.  Boot.ini contains a list of ARC paths.  Ok, quick – five bonus points to the first person who can tell me what ‘ARC’ stands for…  come on…  Yes, you there in the red shirt… correct!  It stands for ‘Advanced RISC Computing’; now beam down with the captain.  The rest of you come with me…


    ARC paths may use the “Multi”, “SCSI” or “Signature” syntax.


    The “Multi” syntax instructs Windows to rely on the system BIOS to load system files.  This means that NTLDR will be using INT13 BIOS calls to find and load NTOSKRNL and any other files on the boot partition.


    The “SCSI” syntax tells Windows to load a SCSI device driver to access the boot partition.  A copy of the driver must be renamed to NTBOOTDD.SYS and placed in the root of the system partition.


    The “Signature” syntax is equivalent to the SCSI syntax, but is used instead to support the Plug and Play architecture in Windows 2000 or later.  Because Windows 2000 is a PnP OS, the SCSI controller number instance might vary each time you start Windows 2000, especially if you add new SCSI controller hardware after setup.


    The Signature syntax instructs NTLDR to locate the drive with a disk signature that matches the value in the parentheses, regardless of which SCSI controller number that the drive is connected to.  Keep in mind that the Signature syntax also requires the presence of an Ntbootdd.sys file in the root of the system partition.  If you recall from the previous post, the disk signature value is located in the MBR.



    signature(8b467c12)disk(1)rdisk(0)partition(2)\winnt="Windows 2000"


          Signature() syntax is used only if one of the following conditions exists:


    ·         The System BIOS or controller hosting the boot partition on which Windows is installed, does not support INT13 Extensions, or has the INT13 Extensions option disabled, and the partition on which you installed Windows is either larger than ~7.8 gigabytes (GB) in size, or the ending cylinder number for that partition is higher than 1024.

    ·         The drive on which you installed Windows is connected to a SCSI controller with SCSI BIOS disabled, so INT13 BIOS calls cannot be used during the boot process.


                            227704 Windows May Use Signature() Syntax in the Boot.ini File



    7.    If Boot.ini is not found, NTLDR attempts to continue the boot process by assuming that Windows was installed in the default location on the same partition (c:\windows).  If the c:\windows directory is not found, NTLDR displays this error message:  Windows could not start because the following file is missing or corrupt: \winnt root\system32\ntoskrnl.exe


    8.    If the boot loader screen is displayed, the user must select an operating system to boot.

    a.    If the user chooses to run an operating system other than Windows 2003/XP such as DOS or Windows 95/98, NTLDR loads and executes the Bootsect.dos file located in the root of the boot drive.

    (1)  If the Bootsect.dos file is found, NTLDR loads it into RAM and then passes control to it.

    (2)  Bootsect.dos then loads IO.sys, MSDOS.sys, Command.com, etc., as necessary and proceeds to boot the downlevel operating system.

    (3)  If the file is not found in the root, NTLDR displays:

    I/O Error accessing boot sector file multi(0)disk(0)rdisk(0)partition(1): \bootsect.dos

    b.    If the user selects a Windows NT-based operating system, NTLDR executes Ntdetect.com.

    (1)  If the ARC path points to a hard drive or partition that is not on the system, the following is displayed:

    Windows could not start because of a computer disk hardware configuration problem.  Could not read from the selected boot disk.  Check boot path and disk hardware.  Please check the Windows documentation about hardware disk configuration and your hardware reference manuals for additional information.

    (2)  The above message may also be displayed if you are using Signature() ARC path notation and the disk signature in the MBR is overwritten (for example, by a virus) or changed (corrupted) so that it no longer matches the Signature() value in the Boot.ini file.  The following error message may also be displayed when there are problems with the Signature () value:

    Windows could not start because of the following ARC firmware boot configuration problem: did not properly generate ARC name for HAL and system paths. Please check the Windows documentation about ARC configuration options and your hardware reference manuals for additional information.


    9.    Ntdetect.com initializes and detects all supported hardware that it can find.  (Troubleshooting tip:  There is an Ntdetect.chk on the Windows Resource Kit CD in the Debug.cab file, which can be renamed and used in place of Ntdetect.com to view what Ntdetect.com is detecting during startup.  You know you want to – go ahead, I’ll wait…)


    Ntdetect.com detects the following components:


    a)    Computer ID

    b)    Bus/adapter type

    c)    Video adapter

    d)    Keyboard

    e)    Communications ports

    f)     Floppy disks

    g)    Mouse or other pointing devices

    h)    Parallel ports


    10.  Ntdetect.com passes its list of hardware components to NTLDR.


    11.  If the /SOS switch was used in the Boot.ini for the OS that is loading, NTLDR will display the files it loads into memory from this point on.  Keep in mind – none of these files are being initialized.  They are just being loaded into RAM at this point.  I can’t tell you how many times someone has incorrectly concluded that there is a problem with MUP.SYS because it’s the last file displayed on this screen before their computer hangs.  Poor MUP – always getting a bad rap.  This list can be useful, however; it can help you identify potential malware that may be loading.


    12.  NTLDR loads Ntoskrnl.exe and Hal.dll into memory.  Again, *loading*, not initializing.


    13.  NTLDR loads the System registry hive into memory.  If Windows cannot load the registry hive, it may be necessary to restore the System hive from the ERD or by using the Windows Recovery Console to copy the files from the Windows\Repair or Windows\Repair\RegBack folder.


    14.  NTLDR reads the HKLM\System\Select registry key.

    a.    If the Last Known Good option was not selected, NTLDR looks for the “Default” value in the SELECT key to select which ControlSet to use.  (0x1 = ControlSet001, 0x2 = ContolSet002, 0x3 = ControlSet003) 

    b.    If the Last Known Good option was selected, NTLDR looks for the “LastKnownGood” value in the SELECT key to select the ControlSet to use.


    15.  NTLDR sets the “Current” value in the HKLM\System\Select key to the ControlSet being used.


    Note:  At this point, NTLDR has determined which ControlSet it needs to use, but we don’t actually create the “CurrentControlSet” symbolic link until the kernel initializes (more on that in our next installment).  Therefore, for the purposes of this discussion, I’ll use *ActiveControlSet* to refer to whichever registry ControlSet has been identified as the one NTLDR needs to use.


    16.  NTLDR scans HKLM\System\*ActiveControlSet*\Control\Nls\Codepage for the “Acp”, “Oemcp”, and “Oemhal” values.  These entries are pointers to the table of codepage information stored in the same key.  The table has the filenames that correspond to the codepage numbers.  NTLDR loads these files into memory.  The defaults are C_1252.nls, C_437.nls, and Vgaoem.fon.


    A code page is a character set specific to an operating system or hardware platform.  It maps character codes to individual characters.  Different code pages include different special characters, typically customized for a language or a group of languages.  The system uses code pages to translate keyboard input into character values for non-Unicode based applications, and to translate character values into characters for non-Unicode based output displays.


    17.  NTLDR scans HKLM\System\*ActiveControlSet*\Control\Nls\Language for the “Default” value.  This entry is a pointer to the table of language information stored in the same key.  NTLDR loads this file into memory.  The default is L_intl.nls.


    18.  NTLDR scans HKLM\System\*ActiveControlSet*\Services for device drivers with a “Start” value of 0x0.  It finds their “Group” and “Tag” values also.


    19.  NTLDR scans HKLM\System\*ActiveControlSet*\Control\ServiceGroupOrder for the order that service groups should be loaded.


    20.  NTLDR sorts the drivers by “Group” and then by their “Tag” value.  Each service or driver has a particular group to which it belongs.  All drivers within a specific group are ordered by tag. 


    21.  NTLDR loads the 0x0 device drivers into memory.  It does not initialize or start these drivers.


    22.  The board is set, and the pieces are moving.  NTLDR executes Ntoskrnl.exe.


    Troubleshooting the Boot Loader Phase


    Okay, now that we’ve seen what is supposed to happen, what could possibly go wrong?  Well, several things…


    First, all file-system activity during this phase uses BIOS Int13, Extended Int13 or Ntbootdd.sys. 


    1.    If your computer uses Extended Int 13, verify that Ext. Int13 is enabled in your system’s BIOS or SCSI BIOS as appropriate.


    2.    If you are using a SCSI driver, verify that you are using the correct SCSI driver (Ntbootdd.sys).  If you are using "SCSI()" syntax in the Boot.ini file, copy the correct device driver for the SCSI controller to the root and then rename it to Ntbootdd.sys.  This is the driver that is stored in the Winnt.sbs\System32\Drivers folder (for example, the Aic78xx.sys file).  If you use "MULTI()" syntax in the Boot.ini file, you do not need to do this.  Use the Windows Recovery Console or a Windows NT boot floppy to complete this step.


                301680 HOW TO: Create a Boot Disk for an NTFS or FAT Partition



    307654 How to install and use the Recovery Console in Windows XP




    Significant Errors during this phase:


    ·         Windows could not start because of a computer disk hardware configuration problem.  Could not read from the selected boot disk.  Check boot path and disk hardware.  Please check the Windows documentation about hardware disk configuration and your hardware reference manuals for additional information.


    This error indicates that the ARC path is pointing to a hard drive or partition that is not on the system.  This message may also be displayed if you are using Signature() ARC path notation and the disk signature in the MBR is overwritten (for example, by a virus) or changed (corrupted) so that it no longer matches the Signature() value in the Boot.ini file. 


    ·         Windows could not start because of the following ARC firmware boot configuration problem: did not properly generate ARC name for HAL and system paths. Please check the Windows documentation about ARC configuration options and your hardware reference manuals for additional information.


    This error message may be displayed when there are problems with the Signature () ARC path syntax.


    Ntoskrnl.exe missing or corrupt.  This error could be the result of an incorrect ARC path in the Boot.ini file.  Use the information in the following knowledge base articles to correct the Boot.ini information.


                102873 BOOT.INI and ARC Path Naming Conventions and Usage



                155222 How to Determine the ARC Path



                130921 Creating an FT Boot Disk With Scsi( ) and Multi( ) Identifiers



    It is also possible to use the Windows XP Recovery Console to create a new Boot.ini for a Windows NT, Windows 2000 or .NET installation.  Please see the following knowledge base article for a description of this process:


                291980 A Discussion About the Bootcfg Command and Its Uses



    Specify the /SOS switch in the Boot.ini file and monitor the output to the screen.  If the system stops responding before anything is output to the screen, then the problem may be with hardware detection.  Replace Ntdetect.com with Ntdetect.chk to view the hardware detected by the system during this phase.


                103659 Setup Hangs While Inspecting Hardware; How to Use Ntdetect.com



                320040 HOW TO: Use Ntdetect.chk to Identify Hardware Problems




    Incorrect HAL

    If after specifying the /SOS option, you see that an incorrect version of the HAL.DLL is loading, use the following KB articles to replace the HAL or troubleshoot other HAL-related issues:


                314477 "Hardware Configuration Problem" Err Msg Starting Windows



                237556 Troubleshooting Windows 2000 Hardware Abstraction Layer Issues



    330184  "Invalid Boot.ini" or "Windows could not start" error messages




    Unable to load System hive

    Several problems could happen here.  First, consider that the amount of memory we’re dealing with is only 16MB.  We have to squeeze NTLDR, the System Registry Hive, the kernel, the HAL, all the boot drivers and the PFN database into a relatively small area.  So, with Windows Server 2003, we’ve given ourselves a bit more room. 


                302594 The System hive memory limitation is improved in Windows Server 2003



    If Windows is unable to load the System registry hive into memory, then it may be necessary to restore the System hive from the ERD or use the Windows Recovery Console to copy the files from the Winnt\Repair or Winnt\Repair\RegBack folder whichever version is most recent.


                307545 How to Recover from a Corrupted Registry




    Table of Startup Type Values


    0x0 = Boot

    Loaded into RAM by the Boot loader (NTLDR) during Boot Loader Phase, then initialized by the Kernel (NTOSKRNL) during Kernel Phase

    0x1 = System

    Loaded and initialized by the Kernel during Kernel Phase

    0x2 = Auto

    Loaded or started automatically at system startup

    0x3 = Manual

    Driver is manually started by the user or another process

    0x4 = Disabled

    Driver is not to be started (There are exceptions, such as NTFS)




    Well folks, we certainly have covered a lot of ground so far.  Any questions?  Yes, you there in the front…  Ah, why have we not discussed any blue screens?  Very good question.  We haven’t seen any BSOD’s up to this point in the boot sequence because the kernel isn’t running yet and STOP errors are generated by the kernel.  No kernel, no blue screens. 


    That’s all the time we have this week boys & girls.  Join us next time for How Windows Starts Up, The Kernel Phase.


  • Ntdebugging Blog

    Debugging a Windows 8.1 Store App Crash Dump


    Quality reports on the App Summary page

    Microsoft provides triage dumps of your Windows Store application’s crashes and hangs through the Quality section of the App Summary page on the Dev Center - Windows Store apps portal.


    Back in June 2012, the Windows Store team posted an article on this feature and the basics of debugging the dumps provided.  Improving apps with Quality reports,



    This article digs further into the debugging of Windows Store application crash dump files, and explains the recent changes made to exception reporting in Windows 8.1.


    The files being debugged can be obtained from the Quality page or by collecting them yourself using Windows Error Reporting (WER) or the AeDebug feature of Windows.


    An example AeDebug tool is Sysinternals ProcDump. To configure crash dumping, execute the following from an elevated command prompt:


    C:\>md c:\dumps

    C:\>procdump.exe -ma -i c:\dumps


    Windows Runtime Architecture

    The Windows Runtime (WinRT API) is at the core of all Windows Store applications. Similar to how Win32 and.NET sit between the Desktop app and the kernel, the WinRT API sits between the Windows Store app and the kernel.



    In between the WinRT API and app is a layer called the Language Projection layer. This layer projects the C++ centric concepts of WinRT, into language specific concepts.


    The projection of errors through the Language Projection layer is the focus of this article.

    • In WinRT, errors are modeled as IErrorInfo and IRestrictedErrorInfo interfaces.
    • In CLR languages, errors are modeled as exceptions and are represented as class objects derived from System.Exception.
    • In JavaScript, errors are also modeled as exceptions and are represented as JavaScript Exception (JSE) objects.
    • In C/C++, errors are modeled as an interface or a pure HRESULT.



    Because each language has a different concept on how errors are handled, the projection layer needs to use a least common denominator. For errors, that means that just an HRESULT (Error Code) and HSTRING (Error Message) are sent through the projection layer. Any addition information held by WinRT’s interface is not available in the receiving language. And conversely, any additional information held by the language’s object is not available to WinRT.


    If the error becomes unhandled, the HRESULT becomes the Exception Code reported in the Exception Record (of a live debug session or dump file).


    Visual Studio 2013

    Opening a dump file in Visual Studio allows you to see the Exception Record via the MiniDump File Summary. The Exception Code is listed in the Dump Summary section.




    If you Debug the application, the Exception Code‘s Description will be listed in the Output window.




    The call stack of the Exception Record’s context is viewable in the Call Stack window. Depending on the dump’s state, the $exceptionstack pseudo variable can be used in a Watch (or Locals) window to see the stack.




    Note, having the Private PDBs of the application will make the stack output more complete/accurate.


    Debugging Tools for Windows

    Using the Debugging Tools for Windows, the Exception Record can be displayed using the .exr -1 command. The Exception Code’s description can (sometimes) be looked up using the !error <code> command. The context of the exception is changed to with the .ecxr command. The stack is displayed with the k command (knL adds frame numbers and omits source line information).


    0:004> .exr -1

    ExceptionAddress: 722248e8 (msvcr110!Concurrency::details::_ReportUnobservedException+0x00000022)

       ExceptionCode: c0000409 (Security check failure or stack buffer overrun)

      ExceptionFlags: 00000001

    NumberParameters: 1

       Parameter[0]: 00000005


    0:004> !error c0000409

    Error code: (NTSTATUS) 0xc0000409 (3221226505) - The system detected an overrun of a stack-based buffer in this application. This overrun could potentially allow a malicious user to gain control of this application.


    0:004> .ecxr

    eax=00000001 ebx=ffffffff ecx=00000005 edx=0a6ee048 esi=13672424 edi=0546c33c

    eip=722248e8 esp=02ceeef8 ebp=02ceef14 iopl=0         nv up ei pl nz na po nc

    cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202


    722248e8 cd29            int     29h


    0:004> knL

      *** Stack trace for last set context - .thread/.cxr resets it

    # ChildEBP RetAddr 

    00 02ceeef4 00f2f6cb msvcr110!Concurrency::details::_ReportUnobservedException+0x22

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

    01 02ceef14 00f2fad7 MyBadApp+0xef6cb

    02 02ceef40 01122720 MyBadApp+0xefad7

    03 02ceef64 011228eb MyBadApp+0x2e2720

    04 02ceef70 00f3960a MyBadApp+0x2e28eb

    05 02ceefb0 010cc804 MyBadApp+0xf960a

    06 02ceefc0 0112108e MyBadApp+0x28c804

    07 02ceeff8 72422b61 MyBadApp+0x2e108e

    08 02cef034 72427e27 Microsoft_Xbox!DllGetClassObject+0x61352

    09 02cef040 76095c3e Microsoft_Xbox!DllGetClassObject+0x66618

    0a 02cef060 7610f497 rpcrt4!Invoke+0x2a

    0b 02cef6ec 75c241f8 rpcrt4!NdrStubCall2+0x33c

    0c 02cef734 75c1f58a combase!CStdStubBuffer_Invoke+0xc1

    0d 02cef7c0 75b24617 combase!SyncStubInvoke+0x144

    0e (Inline) -------- combase!StubInvoke+0x9a

    0f 02cef8e8 75b97d8d combase!CCtxComChnl::ContextInvoke+0x222

    10 02cef90c 75c24cc9 combase!DefaultInvokeInApartment+0x30

    11 (Inline) -------- combase!ASTAInvokeInApartment+0x35

    12 02cef9b4 75c1fdc7 combase!AppInvoke+0x5ae

    13 02cefb00 75c24c71 combase!ComInvokeWithLockAndIPID+0x5ed

    14 02cefb20 75b93118 combase!ComInvoke+0x153

    15 02cefb30 75b97b11 combase!ThreadDispatch+0x23

    16 02cefb44 75be53b5 combase!CComApartment::ASTAHandleMessage+0xe6

    17 02cefb68 75ba8f22 combase!ASTAWaitContext::DispatchCallsOnExitNonBlockingProcessEventsIfAppropriate+0x9e

    18 02cefb8c 75b5917e combase!ASTAWaitContext::~ASTAWaitContext+0x1a9

    19 02cefb98 74acb13d combase!CoEndProcessEvents+0x37

    1a 02cefbf4 00f733d7 windows_ui!Windows::UI::Core::CDispatcher::ProcessEvents+0x29ac1

    1b 02cefc64 00f77f46 MyBadApp+0x1333d7

    1c 02cefc94 74f6f45e MyBadApp+0x137f46

    1d 02cefca0 74f6f322 twinapi_appcore!Windows::ApplicationModel::Core::CoreApplicationView::Run+0x27

    1e 02cefcc0 74b1008a twinapi_appcore!<lambda_f0454c86bc54370cf843d844d6c13e00>::operator()+0xb2

    1f 02cefd44 75f4a534 SHCore!_WrapperThreadProc+0xe2

    20 02cefd50 77dd8f8b kernel32!BaseThreadInitThunk+0xe

    21 02cefd94 77dd8f61 ntdll!__RtlUserThreadStart+0x20

    22 02cefda4 00000000 ntdll!_RtlUserThreadStart+0x1b


    Simple so far...

    Using Visual Studio or the Debugging Tools for Windows is relatively simple when the Exception Record is associated with the call stack of the issue. This is not however always the case. It depends on what side of the projection layer the issue occurred. If the error (exception) was not handled on the language side, the exception is marshaled (projected) to the WinRT side for its exception handling. When this occurs, it starts getting very, very tricky indeed, to see what stack caused the issue...


    Language Exceptions - Error Code 0xC000027B

    In the initial design of the WinRT API, the projection of errors was done though a call to the RoOriginateError function. This function takes a HRESULT and HSTRING. Of note, there is no call stack captured. The limits of the RoOriginateError function were recognized and a new (associated) function was created for Windows 8.1.


    The RoOriginateLanguageException function takes a HRESULT, HSTRING and a marshalable interface pointer. When RoOriginateLanguageException in called, the current call stack is captured and is passed as part of the error.


    The purpose of RoOriginateLanguageException is to marshal the interface pointer so that additional language information is available on the other side of the projection layer. This behavior is achieved by using a specific exception code. Instead of the using the (user defined) HRESULT, a value of 0xC000027B is used. This error code indicates to the receiver that there is data to unmarshal. The data includes the HRESULT and HSTRING, and also the Interface pointer.


    The important point to understand here is that all async exceptions raised in Windows 8.1 Windows Store apps now result in a 0xC000027B error code in the Exception Record, not the error code passed by the caller.


    Debugging Language Exceptions

    The Exception Record of a Language Exception contains (of note) the exception code (0xC000027B) and two parameters.


    0:004> .exr -1

    ExceptionAddress: 73034fec (Windows_UI_Xaml!DirectUI::ErrorHelper::ProcessUnhandledError+0x000000b8)

       ExceptionCode: c000027b

      ExceptionFlags: 00000001

    NumberParameters: 2

       Parameter[0]: 0bdaf240

       Parameter[1]: 00000001


    0:006> !error c000027b

    Error code: (NTSTATUS) 0xc000027b (3221226107) - An application-internal exception has occurred.


    The first parameter is the address of a pointer array (of unmarshalled data). The second parameter is the count of pointers in the pointer array.


    So why is the need for a count?  Since applications have multiple threads, it is possible for multiple threads to call RoOriginateLanguageException simultaneously. Equally, there can be a cyclic nature to the experience, where exceptions are caught and then re-thrown. Since WinRT processes the errors asynchronously, multiple errors exist regularly. The first exception in the array should be the focus of the investigation.


    [Tip] Even though Microsoft publishes the private symbols for combase.dll (allowing you to view the local variables of combase!RoFailFast* functions), these locals regularly resolve to invalid addresses due to register reuse and other code flow optimizations. The pointer array in Parameter[0] is the correct place to get the address of the language exception pointer array.


    Original Error Code

    The first step when debugging a Language Exception is to determine the actual error code of the caller, instead of the 0xC000027B error code.


    Casting an address to a pointer array of a specific type in Visual Studio is, put simply, too difficult to undertake. The easiest option is to use the Debugging Tools for Windows. Even though these tools are all command-line driven and use an obscure syntax, it is relatively easy to follow the following commands to get to the important information.


    If not done already, set your symbol path to the Microsoft Public Symbol server:


    0:004> .sympath SRV*C:\Symbols*http://msdl.microsoft.com/download/symbols

    Symbol search path is: SRV*C:\Symbols*http://msdl.microsoft.com/download/symbols

    Expanded Symbol search path is: srv*c:\Symbols*http://msdl.microsoft.com/download/symbols

    ************* Symbol Path validation summary **************

    Response                         Time (ms)     Location

    Deferred                                       SRV*C:\Symbols*http://msdl.microsoft.com/download/symbols


    Force the load of the symbols using the .reload /f command:


    0:004> .reload /f



    The next step is to display the pointer array as the original structure type. First, we need to know what structure to cast the pointer array to. Using the Parameter[0] value from .exr -1, we will generate a dt command that will display the header of the first record. We use Parameter[0] as the address in this command.


    dt <Parameter[0]> combase!_STOWED_EXCEPTION_INFORMATION_HEADER*


    Here’s an example:


    0:004> .exr -1

    ExceptionAddress: 73034fec (Windows_UI_Xaml!DirectUI::ErrorHelper::ProcessUnhandledError+0x000000b8)

       ExceptionCode: c000027b

      ExceptionFlags: 00000001

    NumberParameters: 2

       Parameter[0]: 0180cf90

       Parameter[1]: 00000003


    0:004> dt 0180cf90 combase!_STOWED_EXCEPTION_INFORMATION_HEADER*


       +0x000 Size             : 0x20

       +0x004 Signature        : 0x53453031


    The value of the Signature member (0x53453031) is converted to a string using .formats <value>.


    0:006> .formats 0x53453031

    Evaluate expression:

      Hex:     53453031

      Decimal: 1397043249

      Octal:   12321230061

      Binary:  01010011 01000101 00110000 00110001

      Chars:   SE01

      Time:    Wed Apr 09 04:34:09 2014

      Float:   low 8.46917e+011 high 0

      Double:  6.90231e-315


    The chars “SE01” map to a structure name of combase!_STOWED_EXCEPTION_INFORMATION_V1. It can be assumed that v2 uses a signature of “SE02” and a structure name of combase!_STOWED_EXCEPTION_INFORMATION_V2, and so on…


    Now we know the type, we can again use the values from .exr -1 to generate a dt command that will display each record. We use the Parameter[0] as the address, and Parameter[1] as the count in the command. We add an “*” to the end of the type as this is an array of pointers to the type, not structures packed next to each other.


    In this example, there are 3 pointers, so 3 records are displayed:


    dt -a<Parameter[1]> <Parameter[0]> combase!_STOWED_EXCEPTION_INFORMATION_V1*


    Note, there is no space between the -a and <Parameter[1]>.


    0:004> .exr -1

    ExceptionAddress: 73034fec (Windows_UI_Xaml!DirectUI::ErrorHelper::ProcessUnhandledError+0x000000b8)

       ExceptionCode: c000027b

      ExceptionFlags: 00000001

    NumberParameters: 2

       Parameter[0]: 0180cf90

       Parameter[1]: 00000003


    0:004> dt -a3 0180cf90 combase!_STOWED_EXCEPTION_INFORMATION_V1*

    [0] @ 0180cf90



       +0x000 Header           : _STOWED_EXCEPTION_INFORMATION_HEADER

       +0x008 ResultCode       : 80131500

       +0x00c ExceptionForm    : 0y01

       +0x00c ThreadId         : 0y000000000000000000010100111100 (0x53c)

       +0x010 ExceptionAddress : 0x7721ea23 Void

       +0x014 StackTraceWordSize : 4

       +0x018 StackTraceWords  : 5

       +0x01c StackTrace       : 0x06f48418 Void

       +0x010 ErrorText        : 0x7721ea23  "?????"


    [1] @ 0180cf94



       +0x000 Header           : _STOWED_EXCEPTION_INFORMATION_HEADER

       +0x008 ResultCode       : 80131500

       +0x00c ExceptionForm    : 0y01

       +0x00c ThreadId         : 0y000000000000000000010100111100 (0x53c)

       +0x010 ExceptionAddress : (null)

       +0x014 StackTraceWordSize : 4

       +0x018 StackTraceWords  : 0x19

       +0x01c StackTrace       : 0x071c926c Void

       +0x010 ErrorText        : (null)


    [2] @ 0180cf98



       +0x000 Header           : _STOWED_EXCEPTION_INFORMATION_HEADER

       +0x008 ResultCode       : 80131534

       +0x00c ExceptionForm    : 0y01

       +0x00c ThreadId         : 0y000000000000000000010100111100 (0x53c)

       +0x010 ExceptionAddress : (null)

       +0x014 StackTraceWordSize : 4

       +0x018 StackTraceWords  : 9

       +0x01c StackTrace       : 0x071c8224 Void

       +0x010 ErrorText        : (null)


    The ResultCode member is 80131500 in the first two records, and 80131534 in the third record. A quick use of the !error <code> command looks up the descriptions:


    0:007> !error 80131500

    Error code: (HRESULT) 0x80131500 (2148734208) - <Unable to get error code text>


    0:007> !error 80131534

    Error code: (HRESULT) 0x80131534 (2148734260) - <Unable to get error code text>


    In this case, both aren‘t well-known error codes. This is common as API specific error codes aren’t in the OS error lookup routines.


    Here are some examples of known error codes, found by looking at a random selection of dumps. Some are quite common (80004003, 80004005 and 80070057) while others are quite rare:


    0:004> !error 80004003

    Error code: (HRESULT) 0x80004003 (2147500035) - Invalid pointer


    0:004> !error 80004005

    Error code: (HRESULT) 0x80004005 (2147500037) - Unspecified error


    0:005> !error 8000ffff

    Error code: (HRESULT) 0x8000ffff (2147549183) - Catastrophic failure


    0:004> !error 80070057

    Error code: (HRESULT) 0x80070057 (2147942487) - The parameter is incorrect.


    0:006> !error 80073db8

    Error code: (HRESULT) 0x80073db8 (2147958200) - Loading the state store failed.


    0:005> !error 800f1000

    Error code: (HRESULT) 0x800f1000 (2148470784) - No installed components were detected.


    0:006> !error 88985004

    Error code: (HRESULT) 0x88985004 (2291683332) - A font file exists but could not be opened due to access denied, sharing violation, or similar error.


    Original Call Stack

    Regardless of whether the error code is known or unknown, it is useful to determine the location of the issue by viewing the call stack.


    Symbol Pointers

    If the ExceptionForm member has a value of 0y01, the structure’s union represents a call stack.


    Unlike call stacks associated with threads, where the symbol pointers are placed throughout the stack next to local variables, these symbols pointers are packed tightly at the address specified in the StackTrace member. The dpS command is used to display the call stack.

    • It is important to include a limit (L) as the call stack is regularly longer than the default 10 rows displayed by dpS. The limit’s value is in the StackTraceWords member.
    • Note that capital S is used (dps vs dpS) because we want to omit the first column normally displayed by dps; the location of the symbol pointer is irrelevant.
    • If you aren‘t using the same bitness debugger as the target’s bitness, use ddS for StackTraceWordSize = 4, and dqS for StackTraceWordSize = 8.


    0:004> dt -a3 0180cf90 combase!_STOWED_EXCEPTION_INFORMATION_V1*

    [0] @ 0180cf90



       +0x000 Header           : _STOWED_EXCEPTION_INFORMATION_HEADER

       +0x008 ResultCode       : 80131500

       +0x00c ExceptionForm    : 0y01

       +0x00c ThreadId         : 0y000000000000000000010100111100 (0x53c)

       +0x010 ExceptionAddress : 0x7721ea23 Void

       +0x014 StackTraceWordSize : 4

       +0x018 StackTraceWords  : 5

       +0x01c StackTrace       : 0x06f48418 Void

       +0x010 ErrorText        : 0x7721ea23  "?????"



    0:007> dpS 0x06f48418 L5

    7723f217 combase!RoOriginateLanguageException+0x3b

    72e29bfd clr!SetupErrorInfo+0x1e1

    72ef27e1 clr!MarshalNative::GetHRForException_WinRT+0x7d

    71981170 Windows_UI_Xaml_ni+0x291170

    72b02a36 clr!COMToCLRDispatchHelper+0x28


    Unicode String Pointer

    If the ExceptionForm member has a value of 0y10, the structure’s union represents an error message.


    The call stack is (hopefully) contained within the Unicode string pointed at by the ErrorText member. As the text is defined by the caller, the existence of a call stack text isn’t guaranteed.


    0:005> dt –a1 13f117e0 combase!_STOWED_EXCEPTION_INFORMATION_V1*

    [0] @ 13f117e0



       +0x000 Header           : _STOWED_EXCEPTION_INFORMATION_HEADER

       +0x008 ResultCode       : 8000ffff

       +0x00c ExceptionForm    : 0y10

       +0x00c ThreadId         : 0y000000000000000000010101110100 (0x574)

       +0x010 ExceptionAddress : 0x0de38f7c Void

       +0x014 StackTraceWordSize : 0

       +0x018 StackTraceWords  : 0

       +0x01c StackTrace       : (null)

       +0x010 ErrorText        : 0x0de38f7c  "System.Exception..   at Windows.UI.Xaml.VisualStateManager.GoToState(Control control, String stateName, Boolean useTransitions)..   at MyBadApp.Common.LayoutAwarePage.InvalidateVisualState()..   at MyBadApp.Common.LayoutAwarePage.WindowSizeChanged(Object sender, WindowSizeChangedEventArgs e)"


    CLR - Last Exception Object

    Sometimes, the call stack retrieved from the record isn’t that useful. It may just be the call stack leading up to RoOriginateLanguageException function call, or it just might not relate to any of the code that the application author has written. In these cases, the CLR provides one more chance to understand the issue.


    When the CLR throws an exception on a managed thread, the address of the exception object is kept in an (internal) per-thread variable. This address is what the !sos.pe (print exception) command reads to display the CLR Last Exception of a thread.


    Note, if you use the Windows 8.1 SDK version of the Debugging Tools for Windows, SOS will be automatically loaded for you, including the download of any required DLLs. As such, it is highly suggested that you use the Windows 8.1 version.


    Example #1

    Looking at this example, we can see that there is a single record with an "Invalid pointer" error.


    0:006> .exr -1

    ExceptionAddress: 00007ffb87c46960 (twinapi_appcore!Microsoft::WRL::ComPtr<Windows::ApplicationModel::Core::UnhandledErrorDetectedEventArgs>::{dtor})

       ExceptionCode: c000027b

      ExceptionFlags: 00000001

    NumberParameters: 2

       Parameter[0]: 0000003fbc80c8a0

       Parameter[1]: 0000000000000001


    0:006> dt -a1 0000003fbc80c8a0 combase!_STOWED_EXCEPTION_INFORMATION_V1*

    [0] @ 0000003f`bc80c8a0



       +0x000 Header           : _STOWED_EXCEPTION_INFORMATION_HEADER

       +0x008 ResultCode       : 80004003

       +0x00c ExceptionForm    : 0y01

       +0x00c ThreadId         : 0y000000000000000000100111001000 (0x9c8)

       +0x010 ExceptionAddress : 0x00007ffb`981e1f1c Void

       +0x018 StackTraceWordSize : 8

       +0x01c StackTraceWords  : 0x18

       +0x020 StackTrace       : 0x0000003f`bd7ac9c0 Void

       +0x010 ErrorText        : 0x00007ffb`981e1f1c  "???"


    0:006> !error 80004003

    Error code: (HRESULT) 0x80004003 (2147500035) - Invalid pointer


    This is a common call stack. A CLR exception is being marshaling to the unhandled error reporting sub-system of WinRT.


    0:006> dpS 0x0000003f`bd7ac9c0 L18

    00007ffb`98238d27 combase!RoOriginateLanguageException+0x57

    00007ffb`71e0f926 mscorlib_ni!DomainNeutralILStubClass.IL_STUB_PInvoke(Int32, System.String, IntPtr)+0xe6

    00007ffb`71ff7084 mscorlib_ni!System.Runtime.InteropServices.WindowsRuntime.WindowsRuntimeMarshal.RoOriginateLanguageException(Int32, System.String, IntPtr)+0x44

    00007ffb`71ff6b8d mscorlib_ni!System.Runtime.InteropServices.WindowsRuntime.WindowsRuntimeMarshal.ReportUnhandledError(System.Exception)+0x12d

    00007ffb`885042f4 System_Runtime_WindowsRuntime_ni!System.Threading.WinRTSynchronizationContext+Invoker.InvokeCore()+0x73e04

    00007ffb`7ee6b915 clr!ExceptionTracker::CallHandler+0xc5

    00007ffb`7ee6b80b clr!ExceptionTracker::CallCatchHandler+0x7f

    00007ffb`7ee6b728 clr!ProcessCLRException+0x2e6

    00007ffb`9a30a7fd ntdll!RtlpExecuteHandlerForUnwind+0xd

    00007ffb`9a2b36ba ntdll!RtlUnwindEx+0x366

    00007ffb`7ee6d1c0 clr!ClrUnwindEx+0x40

    00007ffb`7ee6d174 clr!ProcessCLRException+0x2b2

    00007ffb`9a30a77d ntdll!RtlpExecuteHandlerForException+0xd

    00007ffb`9a2b29fb ntdll!RtlDispatchException+0x19b

    00007ffb`9a2b2668 ntdll!RtlRaiseException+0xf0

    00007ffb`976c8384 KERNELBASE!RaiseException+0x68


    There is a CLR Last Exception object and the exception code of it matches the record’s code:


    0:006> !sos.pe

    Exception object: 0000003fa2be4830

    Exception type:   System.NullReferenceException

    Message:          Object reference not set to an instance of an object.

    InnerException:   <none>

    StackTrace (generated):

        SP               IP               Function

        0000003FBC80D190 00007FFB1F72FC18 MyBadApp!MyBadApp.Utilities.Authentication.GetAliasFromSecurityToken()+0x18

        0000003FBC80D1D0 00007FFB1F72FAC2 MyBadApp! MyBadApp.MainPage.MainPage_AuthenticateUserCompleted(System.Object, System.EventArgs)+0x82

        0000003FBC80D210 00007FFB1F72F5E5 MyBadApp! MyBadApp.MainPage+<AuthenticateUser_Async>d__0.MoveNext()+0x305

        0000003FBC80EE60 00007FFB724F0B31 mscorlib_ni!System.Runtime.CompilerServices.AsyncMethodBuilderCore.<ThrowAsync>b__4(System.Object)+0x4d61d1

        0000003FBC80EE90 00007FFB88490523 System_Runtime_WindowsRuntime_ni!System.Threading.WinRTSynchronizationContext+Invoker.InvokeCore()+0x33


    StackTraceString: <none>

    HResult: 80004003


    In this case, you can surmise that the System.NullReferenceException exception was thrown within the MyBadApp!MyBadApp.Utilities.Authentication.GetAliasFromSecurityToken() function, and that it was unhandled.


    Extraction of the CLR Last Exception object can also sometimes be done in Visual Studio. When you do a Debug with Managed Only on the dump file, the Locals window sometimes contains a pseudo variable called $exception that represents the exception.




    The Text Visualizer of the StackTrace member allows you to see the call stack.




    Example #2

    Looking at another example, we can see that again there is a single record, this time with an "Unspecified error" exception code.


    0:004> .exr -1

    ExceptionAddress: 73034fec (Windows_UI_Xaml!DirectUI::ErrorHelper::ProcessUnhandledError+0x000000b8)

       ExceptionCode: c000027b

      ExceptionFlags: 00000001

    NumberParameters: 2

       Parameter[0]: 0bdaf240

       Parameter[1]: 00000001


    0:004> dt -a1 0bdaf240 combase!PSTOWED_EXCEPTION_INFORMATION_V1

    [0] @ 0bdaf240



       +0x000 Header           : _STOWED_EXCEPTION_INFORMATION_HEADER

       +0x008 ResultCode       : 80004005

       +0x00c ExceptionForm    : 0y01

       +0x00c ThreadId         : 0y000000000000000000010010011110 (0x49e)

       +0x010 ExceptionAddress : (null)

       +0x014 StackTraceWordSize : 4

       +0x018 StackTraceWords  : 5

       +0x01c StackTrace       : 0x0af6302c Void

       +0x010 ErrorText        : (null)


    0:006> !error 80004005

    Error code: (HRESULT) 0x80004005 (2147500037) - Unspecified error


    The call stack of the record suggests that this is associated with GetNavigationState:


    0:004> dpS 0x0af6302c L5

    72ec4e7d Windows_UI_Xaml!DirectUI::NavigationHistory::WritePageStackEntryToString+0x1f7fde

    72ec4ef0 Windows_UI_Xaml!DirectUI::NavigationHistory::GetNavigationState+0x1f7ddf

    72ccd0fa Windows_UI_Xaml!DirectUI::Frame::GetNavigationStateImpl+0x3a

    72cccced Windows_UI_Xaml!DirectUI::FrameGenerated::GetNavigationState+0x2f

    737d00eb Windows_UI_Xaml_ni+0x2400eb


    But the CLR Last Exception object doesn’t have the same exception code as the record:


    0:004> !sos.pe

    Exception object: 02cb3cb8

    Exception type:   <Unknown>

    Message:          <Invalid Object>

    InnerException:   System.Runtime.InteropServices.COMException, Use !PrintException e2a09bc6 to see more.

    StackTrace (generated):

        SP       IP       Function

        052DF6C0 07141094 MyBadApp!UNKNOWN+0x544

        052DF8A4 73E0D17A mscorlib_ni!System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(System.Threading.Tasks.Task)+0x5e

        052DF8B4 73E0D115 mscorlib_ni!System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task)+0x35

        052DF8C0 071409DB MyBadApp!UNKNOWN+0xb3

        052DF8CC 7458458F mscorlib_ni!System.Runtime.CompilerServices.AsyncMethodBuilderCore.<ThrowAsync>b__4(System.Object)+0x33

        052DF8D4 6F9EF994 System_Runtime_WindowsRuntime_ni!System.Threading.WinRTSynchronizationContext+Invoker.InvokeCore()+0x24


    StackTraceString: <none>

    HResult: 80131500


    0:006> !error 80131500

    Error code: (HRESULT) 0x80131500 (2148734208) - <Unable to get error code text>


    It does however have a nested CLR Exception object that does have the same exception code as the record. It too has a call stack that indicates GetNavigationState is having an issue.


    0:004> !PrintException /d 02caf968

    Exception object: 02caf968

    Exception type:   System.Runtime.InteropServices.COMException

    Message:          <Invalid Object>

    InnerException:   <none>

    StackTrace (generated):

        SP       IP       Function

        00000000 00000001 Windows_UI_Xaml_ni!Windows.UI.Xaml.Controls.Frame.GetNavigationState()+0x2

        052DF778 071411B5 MyBadApp!UNKNOWN+0x1d

        052DF788 07140BF3 MyBadApp!UNKNOWN+0xa3


    StackTraceString: <none>

    HResult: 80004005



    The asynchronous and projected nature of Windows Store applications makes them significantly harder to debug than desktop applications. Knowing the error code and call stack is just the first step in understanding the root cause of a crash in a Store application. Hopefully this blog post has made those first steps easier to undertake, and that those first steps have pointed you in the right direction.


    The solutions to some of the more common issues have been talked about on episodes of Channel 9 Defrag Tools. These episodes show the code changes required to avoid the hang or crash:

Page 3 of 24 (240 items) 12345»