• Ntdebugging Blog

    Troubleshooting Pool Leaks Part 1 – Perfmon

    • 7 Comments

    Over the years the NTDebugging Blog has published several articles about pool memory and pool leaks.  However, we haven’t taken a comprehensive approach to understanding and troubleshooting pool memory usage.  This upcoming series of articles is going to tackle pool leaks from the basics to advanced troubleshooting techniques.  Most of the examples will use the Windows Sysinternals tool NotMyFault to generate a leak so our readers will be able to reproduce the described behavior and repeat the troubleshooting steps.

     

    We need to start by understanding what pool is and how it is used.  Pool is virtual memory that is used by drivers in much the same way user mode applications use heap.  A driver developer calls ExAllocatePoolWithTag to get a block of memory that can be used in much the same way a user mode programmer would use memory returned by HeapAlloc or malloc.  The memory manager, which is responsible for managing pool, is able to efficiently handle small allocations by taking a page of virtual memory (typically 4KB) and breaking it up into smaller blocks.  The memory manager is also able to allocate pool in blocks larger than a page.  There are two types of pool a developer can request from ExAllocatePoolWithTag, paged pool and nonpaged pool.  As the names suggest one type of pool memory can be paged out, and the other cannot be paged.  Paged pool is used for most allocations, nonpagedpool is used for memory that will be written or read at an IRQL of DISPATCH_LEVEL or above.

     

    Pool leaks happen when a driver calls ExAllocatePoolWithTag but never calls the corresponding ExFreePool or ExFreePoolWithTag routine.  A leak is different than just high memory utilization, which may happen in normal conditions as load increases.  For example, the srv.sys driver creates work items for incoming requests, and when there is a large amount of SMB traffic to a server the pool usage from srv.sys may increase to handle this traffic.  Typically the differentiation between a leak and high memory usage due to load is that a leak never decreases.  Memory usage that is load related should decrease when the load is reduced.  Monitoring is required to differentiate between these two scenarios.  Performance Monitor (aka perfmon) is typically the most effective tool to begin such an investigation.

     

    The symptom of a pool leak is often poor system performance when the system runs out of pool, or on 64-bit systems the pool may begin to consume a large amount of the available memory.  This symptom makes perfmon an ideal tool to begin troubleshooting as it can be used to identify a wide variety of potential causes of poor performance.  Perfmon is most useful when it is started before a system enters a state of poor performance so that trend data can be analyzed leading up to the problem.

     

    You can use the below commands from an elevated command prompt to collect perfmon data from such a scenario.

     

    First create the data collector.  This command collects data from a variety of counters at a 5 minute interval and is designed to be run for several hours prior to and during a the time a system experiences poor performance (shorter intervals can be used for leaks that happen faster than several hours). We often recommend collecting these counters to perform general performance troubleshooting because we usually don’t know that there is a memory leak until after this data is collected and analyzed.

    Logman.exe create counter PerfLog-Long -o "c:\perflogs\\%computername%_PerfLog-Long.blg" -f bincirc -v mmddhhmm -max 300 -c "\LogicalDisk(*)\*" "\Memory\*" "\Cache\*" "\Network Interface(*)\*" "\Paging File(*)\*" "\PhysicalDisk(*)\*" "\Processor(*)\*" "\Processor Information(*)\*" "\Process(*)\*" "\Redirector\*" "\Server\*" "\System\*" "\Server Work Queues(*)\*" "\Terminal Services\*" –si 00:05:00

     

    Then start collecting data:

    Logman.exe start PerfLog-Long

     

    When the performance problem is being experienced, stop collecting data:

    Logman.exe stop PerfLog-Long

     

    After you have collected the data, open the .blg file in the Performance Monitor MMC snap-in.  Browse to the Memory object, and add the counters “Pool Nonpaged Bytes” and “Pool Paged Bytes”.  This should leave you with a view similar to the below screenshot.

     

    image001

     

    The steadily increasing line in the above screenshot, without a substantial decrease in the line, is an indicator that nonpaged pool memory is being leaked.  If we look at the maximum count we see that nonpaged pool has consumed 540MB.  The significance of this value depends on the amount of RAM in the system.  In this instance the system has 1GB of RAM so nonpaged pool is consuming 54% of the available memory.  We can now conclude that the cause of the performance problem is a nonpaged pool memory leak, which is consuming a large amount of RAM and preventing other components from using this RAM.

     

    Next we need to start investigating which driver has allocated the most pool.  We will begin that in part 2.

  • Ntdebugging Blog

    Event ID 157 "Disk # has been surprise removed"

    • 7 Comments

    Hello my name is Bob Golding and I would like to share information on a new error you may see in the system event log. It is Event ID 157 "Disk <n> has been surprise removed" with Source: disk.  This error indicates that the CLASSPNP driver has received a “surprise removal” request from the plug and play manager (PNP) for a non-removable disk.

     

    What does this error mean?

    The PNP manager does what is called enumerations.  An enumeration is a request sent to a driver that controls a bus, such as PCI, to take an inventory of devices on the bus and report back a list of the devices.  The SCSI bus is enumerated in a similar manner, as are devices on the IDE bus.

     

    These enumerations can happen for a number of reasons.  For example, hardware can request an enumeration when it detects a change in configuration.  Also a user can initiate an enumeration by selecting “scan for new devices” in device manager.  

     

    When an enumeration request is received, the bus driver will rescan the bus for all devices.  It will issue commands to the existing devices as though it was looking for new ones.  If these commands fail on an existing unit, the driver will mark the device as “missing”.  When the device is marked “missing”, it will not be reported back to PNP in the inventory.  When PNP determines that the device is not in the inventory it will send a surprise removal request to the bus driver so the bus driver can remove the device object.

     

    Since the CLASSPNP driver sits in the device stack and receives requests that are destined for disks, it sees the surprise removal request and logs an event if the disk is supposed to be non-removable.  An example of a non-removable disk is a hard drive on a SCSI or IDE bus.  An example of a removable disk is a USB thumb drive.

     

    Previously nothing was logged when a non-removable disk was removed, as a result disks would disappear from the system with no indication.  The event id 157 error was implemented in Windows 8.1 and Windows Server 2012 R2 to log a record of a disk disappearing.

     

    Why does this error happen?

    These errors are most often caused when something disrupts the system’s communication with a disk, such as a SAN fabric error or a SCSI bus problem.  The errors can also be caused by a disk that fails, or when a user unplugs a disk while the system is running.  An administrator that sees these errors needs to verify the heath of the disk subsystem.

     

    Event ID 157 Example:

     

  • Ntdebugging Blog

    Understanding Pool Corruption Part 1 – Buffer Overflows

    • 6 Comments

    Before we can discuss pool corruption we must understand what pool is.  Pool is kernel mode memory used as a storage space for drivers.  Pool is organized in a similar way to how you might use a notepad when taking notes from a lecture or a book.  Some notes may be 1 line, others may be many lines.  Many different notes are on the same page.

     

    Memory is also organized into pages, typically a page of memory is 4KB.  The Windows memory manager breaks up this 4KB page into smaller blocks.  One block may be as small as 8 bytes or possibly much larger.  Each of these blocks exists side by side with other blocks.

     

    The !pool command can be used to see the pool blocks stored in a page.

     

    kd> !pool fffffa8003f42000

    Pool page fffffa8003f42000 region is Nonpaged pool

    *fffffa8003f42000 size:  410 previous size:    0  (Free)      *Irp

                Pooltag Irp  : Io, IRP packets

    fffffa8003f42410 size:   40 previous size:  410  (Allocated)  MmSe

    fffffa8003f42450 size:  150 previous size:   40  (Allocated)  File

    fffffa8003f425a0 size:   80 previous size:  150  (Allocated)  Even

    fffffa8003f42620 size:   c0 previous size:   80  (Allocated)  EtwR

    fffffa8003f426e0 size:   d0 previous size:   c0  (Allocated)  CcBc

    fffffa8003f427b0 size:   d0 previous size:   d0  (Allocated)  CcBc

    fffffa8003f42880 size:   20 previous size:   d0  (Free)       Free

    fffffa8003f428a0 size:   d0 previous size:   20  (Allocated)  Wait

    fffffa8003f42970 size:   80 previous size:   d0  (Allocated)  CM44

    fffffa8003f429f0 size:   80 previous size:   80  (Allocated)  Even

    fffffa8003f42a70 size:   80 previous size:   80  (Allocated)  Even

    fffffa8003f42af0 size:   d0 previous size:   80  (Allocated)  Wait

    fffffa8003f42bc0 size:   80 previous size:   d0  (Allocated)  CM44

    fffffa8003f42c40 size:   d0 previous size:   80  (Allocated)  Wait

    fffffa8003f42d10 size:  230 previous size:   d0  (Allocated)  ALPC

    fffffa8003f42f40 size:   c0 previous size:  230  (Allocated)  EtwR

     

    Because many pool allocations are stored in the same page, it is critical that every driver only use the space they have allocated.  If DriverA uses more space than it allocated they will write into the next driver’s space (DriverB) and corrupt DriverB’s data.  This overwrite into the next driver’s space is called a buffer overflow.  Later either the memory manager or DriverB will attempt to use this corrupted memory and will encounter unexpected information.  This unexpected information typically results in a blue screen.

     

    The NotMyFault application from Sysinternals has an option to force a buffer overflow.  This can be used to demonstrate pool corruption.  Choosing the “Buffer overflow” option and clicking “Crash” will cause a buffer overflow in pool.  The system may not immediately blue screen after clicking the Crash button.  The system will remain stable until something attempts to use the corrupted memory.  Using the system will often eventually result in a blue screen.

     

    NotMyFault

     

    Often pool corruption appears as a stop 0x19 BAD_POOL_HEADER or stop 0xC2 BAD_POOL_CALLER.  These stop codes make it easy to determine that pool corruption is involved in the crash.  However, the results of accessing unexpected memory can vary widely, as a result pool corruption can result in many different types of bugchecks.

     

    As with any blue screen dump analysis the best place to start is with !analyze -v.  This command will display the stop code and parameters, and do some basic interpretation of the crash.

     

    kd> !analyze -v

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

    *                                                                             *

    *                        Bugcheck Analysis                                    *

    *                                                                             *

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

     

    SYSTEM_SERVICE_EXCEPTION (3b)

    An exception happened while executing a system service routine.

    Arguments:

    Arg1: 00000000c0000005, Exception code that caused the bugcheck

    Arg2: fffff8009267244a, Address of the instruction which caused the bugcheck

    Arg3: fffff88004763560, Address of the context record for the exception that caused the bugcheck

    Arg4: 0000000000000000, zero.

     

    In my example the bugcheck was a stop 0x3B SYSTEM_SERVICE_EXCEPTION.  The first parameter of this stop code is c0000005, which is a status code for an access violation.  An access violation is an attempt to access invalid memory (this error is not related to permissions).  Status codes can be looked up in the WDK header ntstatus.h.

     

    The !analyze -v command also provides a helpful shortcut to get into the context of the failure.

     

    CONTEXT:  fffff88004763560 -- (.cxr 0xfffff88004763560;r)

     

    Running this command shows us the registers at the time of the crash.

     

    kd> .cxr 0xfffff88004763560

    rax=4f4f4f4f4f4f4f4f rbx=fffff80092690460 rcx=fffff800926fbc60

    rdx=0000000000000000 rsi=0000000000001000 rdi=0000000000000000

    rip=fffff8009267244a rsp=fffff88004763f60 rbp=fffff8009268fb40

    r8=fffffa8001a1b820  r9=0000000000000001 r10=fffff800926fbc60

    r11=0000000000000011 r12=0000000000000000 r13=fffff8009268fb48

    r14=0000000000000012 r15=000000006374504d

    iopl=0         nv up ei pl nz na po nc

    cs=0010  ss=0018  ds=002b  es=002b  fs=0053  gs=002b             efl=00010206

    nt!ExAllocatePoolWithTag+0x442:

    fffff800`9267244a 4c8b4808        mov     r9,qword ptr [rax+8] ds:002b:4f4f4f4f`4f4f4f57=????????????????

     

    From the above output we can see that the crash occurred in ExAllocatePoolWithTag, which is a good indication that the crash is due to pool corruption.  Often an engineer looking at a dump will stop at this point and conclude that a crash was caused by corruption, however we can go further.

     

    The instruction that we failed on was dereferencing rax+8.  The rax register contains 4f4f4f4f4f4f4f4f, which does not fit with the canonical form required for pointers on x64 systems.  This tells us that the system crashed because the data in rax is expected to be a pointer but it is not one.

     

    To determine why rax does not contain the expected data we must examine the instructions prior to where the failure occurred.

     

    kd> ub .

    nt!KzAcquireQueuedSpinLock [inlined in nt!ExAllocatePoolWithTag+0x421]:

    fffff800`92672429 488d542440      lea     rdx,[rsp+40h]

    fffff800`9267242e 49875500        xchg    rdx,qword ptr [r13]

    fffff800`92672432 4885d2          test    rdx,rdx

    fffff800`92672435 0f85c3030000    jne     nt!ExAllocatePoolWithTag+0x7ec (fffff800`926727fe)

    fffff800`9267243b 48391b          cmp     qword ptr [rbx],rbx

    fffff800`9267243e 0f8464060000    je      nt!ExAllocatePoolWithTag+0xa94 (fffff800`92672aa8)

    fffff800`92672444 4c8b03          mov     r8,qword ptr [rbx]

    fffff800`92672447 498b00          mov     rax,qword ptr [r8]

     

    The assembly shows that rax originated from the data pointed to by r8.  The .cxr command we ran earlier shows that r8 is fffffa8001a1b820.  If we examine the data at fffffa8001a1b820 we see that it matches the contents of rax, which confirms this memory is the source of the unexpected data in rax.

     

    kd> dq fffffa8001a1b820 l1

    fffffa80`01a1b820  4f4f4f4f`4f4f4f4f

     

    To determine if this unexpected data is caused by pool corruption we can use the !pool command.

     

    kd> !pool fffffa8001a1b820

    Pool page fffffa8001a1b820 region is Nonpaged pool

     fffffa8001a1b000 size:  810 previous size:    0  (Allocated)  None

     

    fffffa8001a1b810 doesn't look like a valid small pool allocation, checking to see

    if the entire page is actually part of a large page allocation...

     

    fffffa8001a1b810 is not a valid large pool allocation, checking large session pool...

    fffffa8001a1b810 is freed (or corrupt) pool

    Bad previous allocation size @fffffa8001a1b810, last size was 81

     

    ***

    *** An error (or corruption) in the pool was detected;

    *** Attempting to diagnose the problem.

    ***

    *** Use !poolval fffffa8001a1b000 for more details.

     

     

    Pool page [ fffffa8001a1b000 ] is __inVALID.

     

    Analyzing linked list...

    [ fffffa8001a1b000 --> fffffa8001a1b010 (size = 0x10 bytes)]: Corrupt region

     

     

    Scanning for single bit errors...

     

    None found

     

    The above output does not look like the !pool command we used earlier.   This output shows corruption to the pool header which prevented the command from walking the chain of allocations.

     

    The above output shows that there is an allocation at fffffa8001a1b000 of size 810.  If we look at this memory we should see a pool header.  Instead what we see is a pattern of 4f4f4f4f`4f4f4f4f.

     

    kd> dq fffffa8001a1b000 + 810

    fffffa80`01a1b810  4f4f4f4f`4f4f4f4f 4f4f4f4f`4f4f4f4f

    fffffa80`01a1b820  4f4f4f4f`4f4f4f4f 4f4f4f4f`4f4f4f4f

    fffffa80`01a1b830  4f4f4f4f`4f4f4f4f 00574f4c`46524556

    fffffa80`01a1b840  00000000`00000000 00000000`00000000

    fffffa80`01a1b850  00000000`00000000 00000000`00000000

    fffffa80`01a1b860  00000000`00000000 00000000`00000000

    fffffa80`01a1b870  00000000`00000000 00000000`00000000

    fffffa80`01a1b880  00000000`00000000 00000000`00000000

     

    At this point we can be confident that the system crashed because of pool corruption.

     

    Because the corruption occurred in the past, and a dump is a snapshot of the current state of the system, there is no concrete evidence to indicate how the memory came to be corrupted.  It is possible the driver that allocated the pool block immediately preceding the corruption is the one that wrote to the wrong location and caused this corruption.  This pool block is marked with the tag “None”, we can search for this tag in memory to determine which drivers use it.

     

    kd> !for_each_module s -a @#Base @#End "None"

    fffff800`92411bc2  4e 6f 6e 65 e9 45 04 26-00 90 90 90 90 90 90 90  None.E.&........

    kd> u fffff800`92411bc2-1

    nt!ExAllocatePool+0x1:

    fffff800`92411bc1 b84e6f6e65      mov     eax,656E6F4Eh

    fffff800`92411bc6 e945042600      jmp     nt!ExAllocatePoolWithTag (fffff800`92672010)

    fffff800`92411bcb 90              nop

     

    The file Pooltag.txt lists the pool tags used for pool allocations by kernel-mode components and drivers supplied with Windows, the associated file or component (if known), and the name of the component. Pooltag.txt is installed with Debugging Tools for Windows (in the triage folder) and with the Windows WDK (in \tools\other\platform\poolmon).  Pooltag.txt shows the following for this tag:

     

    None - <unknown>    - call to ExAllocatePool

     

    Unfortunately what we find is that this tag is used when a driver calls ExAllocatePool, which does not specify a tag.  This does not allow us to determine what driver allocated the block prior to the corruption.  Even if we could tie the tag back to a driver it may not be sufficient to conclude that the driver using this tag is the one that corrupted the memory.

     

    The next step should be to enable special pool and hope to catch the corruptor in the act.  We will discuss special pool in our next article.

  • Ntdebugging Blog

    Bcdedit Tips and Tricks For Debugging Part 1

    • 6 Comments

    Hello everyone, my name is Sean Walker, and I am on the Platforms OEM team in Washington.  This article is for those people who have had a hard time switching from the old boot.ini configuration to the new BCD store (myself included). Doing the simple tasks such as enabling kernel debugging over com1 are easy to do with bcdedit.exe or the msconfig GUI, you just enable them and reboot the computer. However, if you need to do something more advanced such as break into the early boot process during resume from hibernation, things get a lot more complicated.

     

    This article has some samples for enabling and disabling debug settings that you may not be familiar with, and a list of bcdedit debug settings for Windows Vista/Server 2008 and Windows 7/Server 2008 R2.  This information has been helpful to me for quickly and accurately getting to the debug at hand rather than fumbling around with bcdedit.  Much of the following information has been taken from various sources, including the windbg help files, the OEM team blog, the MSDN bcdedit reference, and the WHDC debugger site.

     

    NOTE: For the examples below, you will need to run bcdedit.exe from an administrator (UAC-elevated) command prompt.  To output a summary view of the current state of the BCD store, just run "bcdedit.exe" from the command prompt.  To get detailed information about all of the store(s) that Windows knows about, use the following command:

    bcdedit /enum all

     

    What is a BCD store?

    A BCD store is a binary file that contains boot configuration data for Windows, basically it is a small registry file.  Boot applications use the system BCD store, located on the system partition, during the boot process.  You can also create additional BCD stores in separate files but only one store at a time can be designated as the system store.

     

    NOTE: The "/store" switch can be used to specify a particular BCD store for bcdedit commands (instead of the default store).  To enumerate all the settings in another BCD store, in this case e:\bcd_store\BCD, use the following command:

    bcdedit /store e:\bcd_store\BCD /enum all

     

    This will show you which options are currently set, and what their values are.  When /store switch is omitted, the system store is used.

     

    Using bootdebug

    To enable debugging for early boot problems, you may need to enable the bootdebug switch.  This is easy to do with bcdedit:

    bcdedit /set bootdebug on

     

    However, this only sets bootdebug for the current "boot application", which is generally winload.exe, so it does not break into the very early boot process.  There are multiple applications used for booting, hibernating, and resuming (bootmgr.exe, winload.exe and winresume.exe are examples of these).  Each application (called BCD Objects) has its own settings (called BCD Elements) in the BCD store and each can be modified globally and/or individually.

     

    So, to deal with different (or multiple) debug scenarios, you just enable boot debugging based on the boot application you are concerned with.  For early debugging, you can enable bootdebug for bootmgr:

    bcdedit /set {bootmgr} bootdebug on

     

    To set bootdebug for winload.exe (which will most often be your current, and default, boot object) all three of the following will give you the same result:

    bcdedit /set bootdebug on

    bcdedit /set {current} bootdebug on

    bcdedit /set {default} bootdebug on

     

    If you are modifying the settings in another store, or are booted into another OS on the same computer (such as WinPE), you need to specify the location of the BCD store:

    bcdedit /store d:\Boot\BCD /set {default} bootdebug on

     

    Not all of the boot objects have "friendly" names, so you may need to specify the full GUID (Globally Unique ID) to modify it.  As an example, if you wanted to enable bootdebug on resume from hibernation, you would include the identifier (see figure 1) for the "Resume from Hibernate" object:

    bcdedit /set {89a932d0-d5bc-11e0-a0af-00215add5ebc} bootdebug on

     

    image001

    Figure 1: Color coded bcdedit output

     

    Why won't my USB or 1394 debug work?

    When there are multiple debug ports of a certain type in a computer Windows may not default to the correct one for your situation.  This happens most commonly when there are either multiple 1394 host controllers or USB EHCI controllers.  When this occurs it can range from a slight inconvenience (different port is used so the cable needs to be plugged into another port), to complete failure (internal port is used, which is not accessible).  In the case of USB debugging the Intel USB 2.0 specification only provides one debug port, so debugging is not possible if the wrong host controller is used.

     

    There are several caveats with USB debugging, not the least of which is that you need to buy a separate, expensive, debug cable.  Some of the difficulties and implementation details necessary to get USB debugging to work are encompassed in the WHDC USB FAQ and in Setting Up Kernel Debugging with USB 2.0.

     

    NOTE: A correction to the WHDC USB documentation for Windows 7/Windows 2008 R2 is that the busparams switch now takes decimal rather than hexadecimal values, and the "loadoptions" parameter is no longer required.  So, to enable the busparams element (for USB or 1394 debugging) in Vista/2008, you would use something like this:

    bcdedit /set {current} loadoptions busparams=0.1D.7

     

    And the Win7/2008 R2 example would be:

    bcdedit /set {current} busparams 0.29.7

     

    In the case of loadoptions or busparams, deleting the setting is not as easy as changing a flag from yes to no. You must specifically delete the value to get rid of it, and one of the examples below can be used:

     

    For Vista/2008:

    bcdedit /deletevalue {current} loadoptions

     

    And Windows 7/2008 R2:

    bcdedit /deletevalue {current} busparams

     

    Bcdedit settings and examples

    This is just scratching the surface of using bcdedit for your troubleshooting and/or debugging needs, so there are more articles to follow. Part 2 will include some more detailed debugging scenarios, such as Hyper-V guest and host debugging.  Below is a consolidated table with many of the debugging switches/settings as well as a number of different usage examples.

     

    Table of debug-related bcdedit settings

    Option

    Description

    bootdebug

    Enables or disables the boot debugger for a specified boot entry. Although this command works for any boot entry, it is effective only for boot applications.

    Enable value(s): on, 1

    Disable value(s): off, 0

    Bcdedit /set bootdebug on

    debug

    Enables or disables the kernel debugger for a specified boot entry.

    Enable value(s): on, 1

    Disable value(s): off, 0

    /dbgsettings

    Used to modify the global settings for the debug connection (does not include hypervisor).  Values:

    Can change all settings at once instead of using the /set command to change them individually. Usage example:

    bcdedit /dbgsettings 1394 channel:30

    debugport

    Used to specify the debugger type.

    Values:

    Serial port – com1, com2, comx

    1394 port – 1394

    USB port - USB

    channel

    Specifies 1394 channel used.

    Values:

    Decimal integer between 0 and 62, inclusive.

    baudrate

    Used to specify the baud rate of a serial debug port.

    Values: 9600, 19200, 38400, 57600, 115200

    targetname

    Specifies a string to use as the identification for the USB 2.0 connection. This string can be any value.

    Usage example:

    bcdedit /dbgsettings usb targetname:usbdebug

    /hypervisorsettings

    Used the same way as /dbgsettings to configure all settings at once.

    Usage example:

    bcdedit /hypervisorsettings 1394 channel:10

    hypervisordebug

    Enables or disables hypervisor debug mode. This is for debugging a Hyper-V host system.

    Enable value(s): on, 1

    Disable value(s): off, 0

    Usage example:

    bcdedit /set {current} hypervisordebug on

    /noumex

    Specifies that the kernel debugger ignores user-mode exceptions. By default, the kernel debugger breaks for certain user-mode exceptions, such as STATUS_BREAKPOINT and STATUS_SINGLE_STEP. The /noumex parameter is effective only when there is no user-mode debugger attached to the process.

    /start

    This option specifies the debugger start policy. If a start policy is not specified, ACTIVE is the default.

    Values: active, disable, autoenable

    loadoptions

    Used to describe settings that are not covered by other types. One setting that is relevant here is busparams.

    Values: Any value followed by the setting.

    Usage example (Vista/2008):

    bcdedit /set {current} loadoptions busparams=0.1d.0

    busparams

    A boot setting (specified with loadoptions key word) used to point to the PCI address of the debugger in use. The PCI bus, device, and function are used, in the format bb.dd.ff. This is generally used to identify the location of a 1394 or USB debug port. In Vista/2008, hexadecimal values are used, whereas decimal values are used for Win7.

    Values: Decimal values between 0 and 255.

    Usage example:

    In Win7 - bcdedit /set busparams 0.29.0

    In Vista - bcdedit /set loadoptions busparams=0.1d.0

    kernel

    The loadoptions parameter used to point to a different kernel binary. This can be used to test with a checked or instrumented version of the kernel without replacing the existing one. The updated binary MUST be placed in the %windir%\system32 folder to be used

    Values: The 8.3 filename of the replacement kernel include the exe extension.

    Usage examples:

    In Win7 – bcdedit /set kernel kernchk.exe

    In Vista - bcdedit /set loadoptions kernel=kernchk.exe

    hal

    The loadoptions parameter used to point to a different hal binary. This can be used to test with a checked or instrumented version of the kernel without replacing the existing one. The updated binary MUST be placed in the %windir%\system32 folder to be used

    Values: the 8.3 filename of the replacement kernel include the .dll extension.

    Usage examples:

    In Win7 – bcdedit /set hal halchk.dll

    In Vista - bcdedit /set loadoptions hal=halchk.dll

    testsigning

    Controls whether Windows 7, Windows Server 2008, or Windows Vista will load any type of test-signed kernel-mode code. This option is not set by default, which means test-signed kernel-mode drivers on 64-bit versions of Windows 7, Windows Server 2008, and Windows Vista will not load without setting the testsigning switch

    Enable value(s): on, 1

    Disable value(s): off, 0

    Usage example:

    Bcdedit /set testsigning on

     

  • Ntdebugging Blog

    Identifying Global Atom Table Leaks

    • 6 Comments

    Hi, it's the Debug Ninja back again with another debugging adventure.  Recently I have encountered several instances where processes fail to initialize, and a review of available resources showed that there was no obvious resource exhaustion.  A more in depth review found that there were no available string atoms in the global atom table.

     

    Global atoms are organized on a per-session basis.  If atoms cannot be allocated in session 0, services may fail to start or processes launched by various services may fail to start.  However, a user logged in to a different session will not experience any such failures.

     

    String atoms are numbered from 0xC000 through 0xFFFF, providing a maximum of 0x4000 atoms per session.  For more information on atoms, and atom tables, see http://technet.microsoft.com/en-us/query/ms649053.

     

    When there are no more string atoms available, calls to APIs that allocate string atoms will fail.  Because atoms are often allocated at process or dll init time, the most common symptom is that processes fail to initialize.  The process may cleanly exit without an error.  You are likely experiencing this problem if you debug your application and find that the failure originates from an API that allocates string atoms such as RegisterClass, RegisterClassEx, GlobalAddAtom, or AddAtom.

     

    To determine if the global string atom table is full you will need to perform a kernel debug.  This can be a live debug or a post-mortem debug using a dump.

     

    First identify the session where the failures have occurred and set the process context to a process in this session.  In my example, w3wp.exe was launching a process and this process failed to initialize.

     

    2: kd> !process 0 0 w3wp.exe

    PROCESS fffffa8005083060

        SessionId: 0  Cid: 1668    Peb: fffdf000  ParentCid: 08ec

        DirBase: 8a2df000  ObjectTable: fffff8a0128bbe40  HandleCount: 441.

        Image: w3wp.exe

    2: kd> .process /p /r fffffa8005083060

    Implicit process is now fffffa80`05083060

    Loading User Symbols

    .....

     

    Next we need to analyze the global atom table.  The pointer to the table is stored in the UserAtomTableHandle global.

     

    2: kd> dq win32k!UserAtomTableHandle l1

    fffff960`003bf7a8  fffff8a0`05e5bc70

     

    The UserAtomTableHandle has a pointer to a handle table at offset 0x10 in 64-bit, and offset 0x8 in 32-bit.  Note that although the atom table is defined as a _RTL_ATOM_TABLE, the format shown by dt is for user mode and does not apply to the UserAtomTableHandle in kernel mode.

     

    2: kd> dq fffff8a0`05e5bc70+10 l1

    fffff8a0`05e5bc80  fffff8a0`05db7740

    2: kd> dt nt!_HANDLE_TABLE fffff8a0`05db7740

       +0x000 TableCode        : 0xfffff8a0`109c8001

       +0x008 QuotaProcess     : (null)

       +0x010 UniqueProcessId  : 0x00000000`00000184 Void

       +0x018 HandleLock       : _EX_PUSH_LOCK

       +0x020 HandleTableList  : _LIST_ENTRY [ 0xfffff8a0`05db7760 - 0xfffff8a0`05db7760 ]

       +0x030 HandleContentionEvent : _EX_PUSH_LOCK

       +0x038 DebugInfo        : (null)

       +0x040 ExtraInfoPages   : 0n0

       +0x044 Flags            : 0

       +0x044 StrictFIFO       : 0y0

       +0x048 FirstFreeHandle  : 0x10004

       +0x050 LastFreeHandleEntry : 0xfffff8a0`10ca4ff0 _HANDLE_TABLE_ENTRY

       +0x058 HandleCount      : 0x3fc0

       +0x05c NextHandleNeedingPool : 0x10400

       +0x060 HandleCountHighWatermark : 0x3fc1

     

    The FirstFreeHandle contains the handle number that will be given to the next handle allocated from this table.  This value is encoded, to get the next handle number we need to right shift the FirstFreeHandle by 2 bits.

     

    2: kd> ?00010004>>2

    Evaluate expression: 16385 = 00000000`00004001

     

    The result from above, 0x4001, is greater than the number of possible string atoms.  As I mentioned earlier, there is a limit of 0x4000 string atoms.  Now we know that the session is out of string atoms.

     

    The next step is to dump the string atoms to identify whether there is an observable pattern in the leaked strings.  The !atom command only works in user mode, so we need to dump the kernel mode strings manually.  An atom table is comprised of multiple buckets.   Each bucket is the head of a list of atoms.  The buckets start at offset 0x20 in the atom table in 64-bit, and offset 0x10 in 32-bit.

     

    2: kd> dq fffff8a0`05e5bc70+20

    fffff8a0`05e5bc90  fffff8a0`05e5ba60 fffff8a0`05db7be0

    fffff8a0`05e5bca0  fffff8a0`08cf1770 fffff8a0`05e5b3d0

    fffff8a0`05e5bcb0  fffff8a0`05ea9020 fffff8a0`05e5b8e0

    fffff8a0`05e5bcc0  fffff8a0`05ea9b10 fffff8a0`05ea9910

    fffff8a0`05e5bcd0  fffff8a0`05ea9f00 fffff8a0`05e5b650

    fffff8a0`05e5bce0  fffff8a0`05cda290 fffff8a0`05ea9e80

    fffff8a0`05e5bcf0  fffff8a0`05e5b200 fffff8a0`05ea9e30

    fffff8a0`05e5bd00  fffff8a0`05e5b7e0 fffff8a0`06c56210

    2: kd> dq

    fffff8a0`05e5bd10  fffff8a0`06d6b5a0 fffff8a0`05ea9d50

    fffff8a0`05e5bd20  fffff8a0`05e5b790 fffff8a0`05e5b9d0

    fffff8a0`05e5bd30  fffff8a0`06bd9bc0 fffff8a0`05ea9c90

    fffff8a0`05e5bd40  fffff8a0`05e5b0c0 fffff8a0`06ae2020

    fffff8a0`05e5bd50  fffff8a0`05e5b930 fffff8a0`04d2af40

    fffff8a0`05e5bd60  fffff8a0`05e5b690 fffff8a0`05e5b980

    fffff8a0`05e5bd70  fffff8a0`05e5b490 fffff8a0`05e5b410

    fffff8a0`05e5bd80  fffff8a0`05e5ba20 fffff8a0`05e5b4f0

    2: kd> dq

    fffff8a0`05e5bd90  fffff8a0`05e5baa0 fffff8a0`05e5b390

    fffff8a0`05e5bda0  fffff8a0`05e5b840 fffff8a0`05ea9c50

    fffff8a0`05e5bdb0  fffff8a0`05e5b250 00000000`00000000

    fffff8a0`05e5bdc0  00000000`00000000 00000000`00000000

    fffff8a0`05e5bdd0  00000000`00000000 00000000`00000000

    fffff8a0`05e5bde0  00000000`00000000 00000000`00000000

    fffff8a0`05e5bdf0  00000000`00000000 00000000`00000000

    fffff8a0`05e5be00  00000000`00000000 00000000`00000000

     

    The quick and dirty way to dump the buckets is with !list.  I am sure that some will say it is tedious to dump each bucket list by hand and that there are easier ways to accomplish this.  To prevent this article from becoming a lesson on debugger scripting, I am leaving that as an exercise to the reader.

     

    2: kd> !list "-t nt!_RTL_ATOM_TABLE_ENTRY.HashLink -e -x \"du @$extret+10\" fffff8a0`05e5ba60"

    du @$extret+10

    fffff8a0`05e5ba70  "Native"

     

    <snip strings that don't match a pattern>

     

    du @$extret+10

    fffff8a0`0838a120  "ControlOfs0210000000000700"

     

    du @$extret+10

    fffff8a0`0f7ff430  "ControlOfs021A000000000C30"

     

    du @$extret+10

    fffff8a0`162168c0  "ControlOfs020E000000001774"

     

    du @$extret+10

    fffff8a0`08c33870  "ControlOfs01F70000000007F4"

     

    du @$extret+10

    fffff8a0`07c46910  "ControlOfs0202000000000BF8"

     

    du @$extret+10

    fffff8a0`062aab50  "ControlOfs01F5000000001274"

     

    du @$extret+10

    fffff8a0`0777b150  "ControlOfs0202000000000C80"

     

    du @$extret+10

    fffff8a0`07dd3410  "ControlOfs0207000000000F00"

     

    du @$extret+10

    fffff8a0`0f01d190  "ControlOfs0214000000000DAC"

     

    Dumping the atoms I found that there is a continuous pattern of the string ControlOfs followed by 16 hexadecimal numbers.  Some time spent with your favorite search engine should find other reports of atom leaks involving the string ControlOfs, and that these leaks have been identified as a problem in some specific software.  In this instance the programmer using that software needs to change their application to avoid the problem.

  • Ntdebugging Blog

    Understanding Storage Timeouts and Event 129 Errors

    • 6 Comments

    Greetings fellow debuggers, today I will be blogging about Event ID 129 messages.  These warning events are logged to the system event log with the storage adapter (HBA) driver’s name as the source.  Windows’ STORPORT.SYS driver logs this message when it detects that a request has timed out, the HBA driver’s name is used in the error because it is the miniport associated with storport.

     

    Below is an example 129 event:

     

    Event Type:       Warning

    Event Source:     <HBA_Name>

    Event Category:   None

    Event ID:         129

    Date:             4/9/2009

    Time:             1:15:45 AM

    User:             N/A

    Computer:         <Computer_Name>

    Description:

    Reset to device, \Device\RaidPort1, was issued.

     

    So what does this mean?  Let’s discuss the Windows I/O stack architecture to answer this.

     

    Windows I/O uses a layered architecture where device drivers are on a “device stack.”  In a basic model, the top of the stack is the file system.  Next is the volume manager, followed by the disk driver.  At the bottom of the device stack are the port and miniport drivers.  When an I/O request reaches the file system, it takes the block number of the file and translates it to an offset in the volume. The volume manager then translates the volume offset to a block number on the disk and passes the request to the disk driver.  When the request reaches the disk driver it will create a Command Descriptor Block (CDB) that will be sent to the SCSI device.  The disk driver imbeds the CDB into a structure called the SCSI_REQUEST_BLOCK (SRB).  This SRB is sent to the port driver as part of the I/O request packet (IRP).

     

    The port driver does most of the request processing.  There are different port drivers depending on the architecture.  For example, ATAPORT.SYS is the port driver for ATA devices, and STORPORT.SYS is the port driver for SCSI devices.  Some of the responsibilities for a port driver are:

    • Providing timing services for requests.
    • Enforcing queue depth (making sure that a device does not get more requests that it can handle).
    • Building scatter gather arrays for data buffers.

    The port driver interfaces with a driver called the “miniport”.  The miniport driver is designed by the hardware manufacturer to work with a specific adapter and is responsible for taking requests from the port driver and sending them to the target LUN.  The port driver calls the HwStorStartIo() function to send requests to the miniport, and the miniport will send the requests to the HBA so they can be sent over the physical medium (fibre, ethernet, etc) to the LUN.  When the request is complete, the miniport will call StorPortNotification() with the NotificationType parameter value set to RequestComplete, along with a pointer to the completed SRB.

     

    When a request is sent to the miniport, STORPORT will put the request in a pending queue.  When the request is completed, it is removed from this queue.  While requests are in the pending queue they are timed. 

     

    The timing mechanism is simple.  There is one timer per logical unit and it is initialized to -1.  When the first request is sent to the miniport the timer is set to the timeout value in the SRB.  The disk timeout value is a tunable parameter in the registry at: HKLM\System\CurrentControlSet\Services\Disk\TimeOutValue.  Some vendors will tune this value to best match their hardware, we do not advise changing this value without guidance from your storage vendor.

     

    The timer is decremented once per second.  When a request completes, the timer is refreshed with the timeout value of the head request in the pending queue.  So, as long as requests complete the timer will never go to zero.  If the timer does go to zero, it means the device has stopped responding.  That is when the STORPORT driver logs the Event ID 129 error.  STORPORT then has to take corrective action by trying to reset the unit.  When the unit is reset, all outstanding requests are completed with an error and they are retried.  When the pending queue empties, the timer is set to -1 which is its initial value.

    image002

    Each SRB has a timer value set.  As requests are completed the queue timer is refreshed with the timeout value of the SRB at the head of the list.

     

    The most common causes of the Event ID 129 errors are unresponsive LUNs or a dropped request.  Dropped requests can be caused by faulty routers or other hardware problems on the SAN.

     

    I have never seen software cause an Event ID 129 error.  If you are seeing Event ID 129 errors in your event logs, then you should start investigating the storage and fibre network.

  • Ntdebugging Blog

    Tracking down MmSt paged pool usage

    • 6 Comments

     

    A trend that I’ve noticed recently are cases involving paged pool depletion with high MmSt tag usage that remains after trying KB304101 (PoolUsageMaximum). These pool allocations are used by the memory manager for section object prototype PTEs. There are generally only two options when this happens: 1) upgrade to a 64-bit platform, or 2) reduce the size of the volumes. But we may want to know what mapped files are using this memory. Here is how it can be done. Start with !memusage.

     

    5: kd> !memusage

     loading PFN database

    loading (100% complete)

    Compiling memory usage data (99% Complete).

                 Zeroed:  19073 ( 76292 kb)

                   Free:      0 (     0 kb)

                Standby: 1468824 (5875296 kb)

               Modified:    368 (  1472 kb)

        ModifiedNoWrite:   1927 (  7708 kb)

           Active/Valid: 605772 (2423088 kb)

             Transition:      0 (     0 kb)

                    Bad:      0 (     0 kb)

                Unknown:      0 (     0 kb)

                  TOTAL: 2095964 (8383856 kb)

      Building kernel map

      Finished building kernel map

    Scanning PFN database - (100% complete)

     

    Following this you will see the list of mapped files and their control areas.

     

      Usage Summary (in Kb):

    Control Valid Standby Dirty Shared Locked PageTables  name

    8c62a638  1108  945868  3064     0     0     0  mapped_file( $Mft )

     

    The control area is the address at the far left and has a Segment field that contains the total number of PTEs.

     

    5: kd> dt 8c62a638 _CONTROL_AREA Segment->TotalNumberOfPtes

    nt!_CONTROL_AREA

       +0x000 Segment                    :

          +0x004 TotalNumberOfPtes          : 0x1e8b00

     

    The MmSt allocations contain these PTEs so all we need to do is multiply this by the size of a PTE to get the total size of the MmSt allocations for this control area. Note that there may be multiple allocations for this control area, but this number will reflect the total size all these allocations.

     

    5: kd> ?? 0x1e8b00 * sizeof(nt!_MMPTE)

    unsigned int 0xf45800

     

    So now we know the MmSt size in bytes for a single control area, or mapped file. What if we would like to see the totals for all mapped files from the !memusage output? First, place the !memusage output in a text file and remove all header information. You will also need to remove all tail information including the page file and process summaries. Every line should look like these.

     

    8c62a638  1108  945868  3064     0     0     0  mapped_file( $Mft )

    8b06ac18   516      0     0     0     0     0    No Name for File

     

    We want to include the “No Name for File” entries since those are valid mapped files even though the name could not be located. Next strip out everything but the control area address. You can use Excel or any other tool that allows you to select and delete columns in a text file. Now we have a file with a single column of all the control areas on the system. The following debugger command script can be used to process this file.

     

    $$ countptes.txt script

    r $t2 = 0;

     

    $$ Replace the memusage.txt file name with your file name.

    .foreach /f (ca "memusage.txt") {

        r $t1 = @@c++(((nt!_CONTROL_AREA *)(0x${ca}))->Segment->TotalNumberOfPtes);

        .printf "Control Area %p : %d\n", ${ca}, @$t1;

        r $t2 = @$t2 + @$t1;

    }

     

    .printf "Total PTEs : %d\n", @$t2;

    .printf "MmSt size  : %d bytes\n", (@$t2 * @@c++(sizeof(nt!_MMPTE)));

     

    The following command will execute the script.

     

    5: kd> $$><countptes.txt

     

    This will show the number of PTEs for each control area, followed by a summary.

     

    Total PTEs : 62790244

    MmSt size  : 502321952 bytes

     

    A common high user of MmSt allocations is $Mft. The cache manager will hold the MmSt allocations for these file system metadata files at a cost of up to 4 files per PTE. This technique can be used to determine how much $Mft is using MmSt pool memory by first using findstr at a command prompt to isolate just those values from the !memusage output.

     

    C:\Projects>findstr /c:"$Mft" memusage.txt >mftusage.txt

     

    After stripping out the control area addresses with Excel and running the command script you’ll have the size of the MmSt allocations for just the $Mft files. If this is consuming most of the MmSt bytes then you are limited to the options mentioned at the beginning of this article. There may be other options if something else is the primary user but it will likely involve reducing some heavy load on the system.

     

    -Bryan

  • Ntdebugging Blog

    How to track down High CPU in User Mode Applications - A live debug!

    • 6 Comments

     

    Written by Jeff Dailey.

     

    Hello NTDebuggers,  I’d like to talk about a common issue we deal with on a regular basis.   We are often tasked with finding what functions are using CPU within a user mode process / application.  Typically a user will find an application that is using more CPU then they expect it to, and this can affect overall system performance and responsiveness.   

     

    For this exercise I’ve written some contrived sample code called EATCPU.  It’s included at the bottom of the blog post.    The following image of task manager shows EATCPU consuming 41% CPU time.   A customer or user may tell you this does not “normally” happen.  It’s always good to ask what “normal” is.   In this case we will say normal is ~10%.

    clip_image002[6]

    The best case scenario is a live debug on the process that is running at high CPU levels.  If you’re lucky enough to have a customer / user that will let you do a remote debug, and the problem reproduces on demand, you can take the following action.

     

    You need to install the debugging tools for Windows, and set your symbol path.  If at all possible acquire the symbols for the application you are debugging.  We’ll assume that you are the expert that supports said program.  If it’s written in house, get the symbols from the developer.  If it’s from a third party, that vendor may be willing to provide you with symbols for their product.  Microsoft has most of the symbols for our products available on our symbol server on the internet (!sympath srv*DownstreamStore*http://msdl.microsoft.com/download/symbols.)

     

    The next thing is to attach windbg.exe to the process in question.

    From the debuggers directory, type TLIST, this will list your process.  Get the process id and then run WinDBG.EXE –p PROCESSID, or if your debugging a program like EATCPU, you can run WINDBG C:\program\EATCPU.EXE.

     

    After the debugger is attached or the process is started in the debugger, reproduce the problem.


     

    Microsoft (R) Windows Debugger  Version 6.8.0001.0

    Copyright (c) Microsoft Corporation. All rights reserved.

     

     

    ***** WARNING: Your debugger is probably out-of-date.

    *****          Check http://dbg for updates.

     

    CommandLine: eatcpu.exe

    Symbol search path is: srv*C:\symbols*\\symbols\symbols

    Executable search path is:

    ModLoad: 00400000 0041a000   eatcpu.exe

    ModLoad: 779b0000 77b00000   ntdll.dll

    ModLoad: 76780000 76890000   C:\Windows\syswow64\kernel32.dll

    ModLoad: 62bb0000 62cd1000   C:\Windows\WinSxS\x86_microsoft.vc80.debugcrt_1fc8b3b9a1e18e3b_8.0.50727.762_none_24c8a196583ff03b\MSVCR80D.dll

    ModLoad: 75cb0000 75d5a000   C:\Windows\syswow64\msvcrt.dll

    (1090.164): Break instruction exception - code 80000003 (first chance)

    eax=00000000 ebx=00000000 ecx=712b0000 edx=00000000 esi=fffffffe edi=77a90094

    eip=779c0004 esp=0017faf8 ebp=0017fb28 iopl=0         nv up ei pl zr na pe nc

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

    ntdll!DbgBreakPoint:

    779c0004 cc              int     3

    0:000> g

    (1090.11d4): Break instruction exception - code 80000003 (first chance)

    eax=7efa3000 ebx=00000000 ecx=00000000 edx=77a1d894 esi=00000000 edi=00000000

    eip=779c0004 esp=0109ff74 ebp=0109ffa0 iopl=0         nv up ei pl zr na pe nc

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

    ntdll!DbgBreakPoint:

    779c0004 cc              int     3

    0:007> .sympath SRV*c:\websymbols*http://msdl.microsoft.com/download/symbols

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

    0:007> g

    (1090.17d4): Break instruction exception - code 80000003 (first chance)

    eax=7efa3000 ebx=00000000 ecx=00000000 edx=77a1d894 esi=00000000 edi=00000000

    eip=779c0004 esp=0109ff74 ebp=0109ffa0 iopl=0         nv up ei pl zr na pe nc

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

    ntdll!DbgBreakPoint:

    779c0004 cc              int     3

     

    Once the problem has started run the !runaway command.

     

    0:007> !runaway

     User Mode Time

      Thread       Time

       2:c04       0 days 0:01:08.827  ß Note this thread, thread 2:c04 is using more CPU than any other.

       7:17d4      0 days 0:00:00.000  ß Note the other threads are using very little if any CPU.

       6:1a4c      0 days 0:00:00.000

       5:d20       0 days 0:00:00.000

       4:157c      0 days 0:00:00.000

       3:1b28      0 days 0:00:00.000

       1:1134      0 days 0:00:00.000

       0:164       0 days 0:00:00.000

     

    0:007> ~2s  ß Using the thread number 2, set the thread context with the ~Ns command.

    *** WARNING: Unable to verify checksum for eatcpu.exe

    eax=cccccccc ebx=00b93c48 ecx=0000002b edx=00b937a8 esi=00000000 edi=00d9fcf0

    eip=0041169c esp=00d9fcd0 ebp=00d9fd9c iopl=0         nv up ei pl nz na po nc

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

    eatcpu!checkSomething+0x1c:

    0041169c f3ab            rep stos dword ptr es:[edi]  es:002b:00d9fcf0=cccccccc

    0:002> k    ß Dump the call stack using k.

     

    If you look at the following call stack, the applications code in this thread starts where you see EATCPU, the code before that is C  Runtime code for begin thread. I want to trace all the code that is running under being thread.  The assumption here is that I’ll find something looping and eating CPU.  To do this I will use the WT command.   However first I need to specify a beginning address for WT to start trace at.

     

    Let's use UF to Unassemble the Function that started our code by taking the return address of  eatcpu!myThreadFunction.

     

    ChildEBP RetAddr 

    00d9fd9c 00411657 eatcpu!checkSomething+0x1c [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 49]

    00d9fe74 004115a8 eatcpu!trySomething+0x27 [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 45]

    00d9ff58 62bb4601 eatcpu!myThreadFunction+0x38 [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 35]

    00d9ff94 62bb459c MSVCR80D!_beginthread+0x221

    00d9ffa0 768019f1 MSVCR80D!_beginthread+0x1bc

    00d9ffac 77a2d109 kernel32!BaseThreadInitThunk+0xe

    00d9ffec 00000000 ntdll!_RtlUserThreadStart+0x23 [d:\vistartm\base\ntos\rtl\rtlexec.c @ 2695]

    0:002> uf 004115a8 ß This command will unassemble the function at this address beginning to end.  

     

    0:007> uf 004115a8

    eatcpu!myThreadFunction [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 30]:

       30 00411570 55              push    ebp

       30 00411571 8bec            mov     ebp,esp

       30 00411573 81eccc000000    sub     esp,0CCh

       30 00411579 53              push    ebx

       30 0041157a 56              push    esi

       30 0041157b 57              push    edi

       30 0041157c 8dbd34ffffff    lea     edi,[ebp-0CCh]

       30 00411582 b933000000      mov     ecx,33h

       30 00411587 b8cccccccc      mov     eax,0CCCCCCCCh

       30 0041158c f3ab            rep stos dword ptr es:[edi]

       31 0041158e 8b4508          mov     eax,dword ptr [ebp+8]

       31 00411591 8945f8          mov     dword ptr [ebp-8],eax

     

    eatcpu!myThreadFunction+0x24 [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 33]:

       33 00411594 b801000000      mov     eax,1

       33 00411599 85c0            test    eax,eax

       33 0041159b 7410            je      eatcpu!myThreadFunction+0x3d (004115ad)

     

    eatcpu!myThreadFunction+0x2d [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 35]:

       35 0041159d 8b45f8          mov     eax,dword ptr [ebp-8]

       35 004115a0 8b08            mov     ecx,dword ptr [eax]

       35 004115a2 51              push    ecx

       35 004115a3 e880faffff      call    eatcpu!ILT+35(?trySomethingYAHHZ) (00411028)

       35 004115a8 83c404          add     esp,4

       36 004115ab ebe7            jmp     eatcpu!myThreadFunction+0x24 (00411594)

     

    eatcpu!myThreadFunction+0x3d [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 37]:

       37 004115ad 5f              pop     edi

       37 004115ae 5e              pop     esi

       37 004115af 5b              pop     ebx

       37 004115b0 81c4cc000000    add     esp,0CCh

       37 004115b6 3bec            cmp     ebp,esp

       37 004115b8 e8a1fbffff      call    eatcpu!ILT+345(__RTC_CheckEsp) (0041115e)

       37 004115bd 8be5            mov     esp,ebp

       37 004115bf 5d              pop     ebp

       37 004115c0 c3              ret

     

    0:002> wt -or 00411570 ß We will use WT to Watch Trace this code.  I’ve selected the starting address of the myThreadFunction function.  I’ve also specified –or to print the return value of each function.  Wt produces very visual output.  It allows you to quickly identify patterns in the way the code executes that would be much more difficult just using the T (TRACE) command. 

     

        8     0 [  0] ntdll!RtlSetLastWin32Error eax = 0

    >> No match on ret

        8     0 [  0] ntdll!RtlSetLastWin32Error

        2     0 [  0] eatcpu!checkSomething

        1     0 [  1]   eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  1]   eatcpu!_RTC_CheckEsp eax = 0

        9     3 [  0] eatcpu!checkSomething

        1     0 [  1]   eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  1]   eatcpu!_RTC_CheckEsp eax = 0

       12     6 [  0] eatcpu!checkSomething eax = 0

    >> No match on ret

       12     6 [  0] eatcpu!checkSomething

        7     0 [  0] eatcpu!trySomething

        1     0 [  1]   eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  1]   eatcpu!_RTC_CheckEsp eax = 0

       10     3 [  0] eatcpu!trySomething eax = 0

    >> No match on ret

       10     3 [  0] eatcpu!trySomething

        9     0 [  0] eatcpu!myThreadFunction  ß I see a pattern,  a loop.   Beginning of loop.

        1     0 [  1]   eatcpu!ILT+35(?trySomethingYAHHZ)

       60     0 [  1]   eatcpu!trySomething

        1     0 [  2]     eatcpu!ILT+180(?checkSomethingYAHHZ)

       62     0 [  2]     eatcpu!checkSomething

        5     0 [  3]       kernel32!SetLastError

       16     0 [  3]       ntdll!RtlSetLastWin32Error eax = 0

       64    21 [  2]     eatcpu!checkSomething

        1     0 [  3]       eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  3]       eatcpu!_RTC_CheckEsp eax = 0

       71    24 [  2]     eatcpu!checkSomething

        1     0 [  3]       eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  3]       eatcpu!_RTC_CheckEsp eax = 0

       74    27 [  2]     eatcpu!checkSomething eax = 0

       67   102 [  1]   eatcpu!trySomething

        1     0 [  2]     eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  2]     eatcpu!_RTC_CheckEsp eax = 0

       70   105 [  1]   eatcpu!trySomething eax = 0

       18   176 [  0] eatcpu!myThreadFunction  ß End of loop / beginning of loop

        1     0 [  1]   eatcpu!ILT+35(?trySomethingYAHHZ)

       60     0 [  1]   eatcpu!trySomething

        1     0 [  2]     eatcpu!ILT+180(?checkSomethingYAHHZ)

       62     0 [  2]     eatcpu!checkSomething

        5     0 [  3]       kernel32!SetLastError  ß Always look for what might be going wrong! Last error can give you a clue.  We are setting last error at the low level of the loop

     16     0 [  3]       ntdll!RtlSetLastWin32Error eax = 0

       64    21 [  2]     eatcpu!checkSomething

        1     0 [  3]       eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  3]       eatcpu!_RTC_CheckEsp eax = 0

       71    24 [  2]     eatcpu!checkSomething

        1     0 [  3]       eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  3]       eatcpu!_RTC_CheckEsp eax = 0

       74    27 [  2]     eatcpu!checkSomething eax = 0  ß Also note checkSomething is returning ZERO, this might indicate a problem.  You need to look at the code or assembler.

       67   102 [  1]   eatcpu!trySomething

        1     0 [  2]     eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  2]     eatcpu!_RTC_CheckEsp eax = 0

       70   105 [  1]   eatcpu!trySomething eax = 0

       27   352 [  0] eatcpu!myThreadFunction ß End of loop / beginning of loop

        1     0 [  1]   eatcpu!ILT+35(?trySomethingYAHHZ)

       60     0 [  1]   eatcpu!trySomething

        1     0 [  2]     eatcpu!ILT+180(?checkSomethingYAHHZ)

       62     0 [  2]     eatcpu!checkSomething

        5     0 [  3]       kernel32!SetLastError

       16     0 [  3]       ntdll!RtlSetLastWin32Error eax = 0

       64    21 [  2]     eatcpu!checkSomething

        1     0 [  3]       eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  3]       eatcpu!_RTC_CheckEsp eax = 0

       71    24 [  2]     eatcpu!checkSomething

        1     0 [  3]       eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  3]       eatcpu!_RTC_CheckEsp eax = 0

       74    27 [  2]     eatcpu!checkSomething eax = 0

       67   102 [  1]   eatcpu!trySomething

        1     0 [  2]     eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  2]     eatcpu!_RTC_CheckEsp eax = 0

       70   105 [  1]   eatcpu!trySomething eax = 0

       36   528 [  0] eatcpu!myThreadFunction ß End of loop / beginning of loop

        1     0 [  1]   eatcpu!ILT+35(?trySomethingYAHHZ)

       60     0 [  1]   eatcpu!trySomething

        1     0 [  2]     eatcpu!ILT+180(?checkSomethingYAHHZ)

       62     0 [  2]     eatcpu!checkSomething

        5     0 [  3]       kernel32!SetLastError

       16     0 [  3]       ntdll!RtlSetLastWin32Error eax = 0

       64    21 [  2]     eatcpu!checkSomething

        1     0 [  3]       eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  3]       eatcpu!_RTC_CheckEsp eax = 0

       71    24 [  2]     eatcpu!checkSomething

        1     0 [  3]       eatcpu!ILT+345(__RTC_CheckEsp)

        2     0 [  3]       eatcpu!_RTC_CheckEsp eax = 0

       74    27 [  2]     eatcpu!checkSomething eax = 0

       67   102 [  1]   eatcpu!trySomething

    12930 instructions were executed in 12929 events (0 from other threads)

     

    Function Name                               Invocations MinInst MaxInst AvgInst

    eatcpu!ILT+180(?checkSomethingYAHHZ)                 69       1       1       1

    eatcpu!ILT+345(__RTC_CheckEsp)                      210       1       1       1

    eatcpu!ILT+35(?trySomethingYAHHZ)                    70       1       1       1

    eatcpu!_RTC_CheckEsp                                210       2       2       2

    eatcpu!checkSomething                                70      60      74      73

    eatcpu!myThreadFunction                               1     630     630     630

    eatcpu!trySomething                                  71      10      70      68

    kernel32!SetLastError                                70       5       5       5

    ntdll!RtlSetLastWin32Error                           70      16      16      16

     

    0 system calls were executed

     

    eax=cccccccc ebx=00b93c48 ecx=00000002 edx=00b937a8 esi=00000000 edi=00d9fe6c

    eip=0041164c esp=00d9fda8 ebp=00d9fe74 iopl=0         nv up ei pl nz na pe nc

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

    eatcpu!trySomething+0x1c:

    0041164c f3ab            rep stos dword ptr es:[edi]  es:002b:00d9fe6c=cccccccc

     

    0:002> !gle ß Now that we have broken in let's check and see what the last error is using !GLE (Get Last Error)  This dumps out the last error from the TEB.

    LastErrorValue: (Win32) 0x57 (87) - The parameter is incorrect.

    LastStatusValue: (NTSTATUS) 0xc000000d - An invalid parameter was passed to a service or function.

     

    0:007> bp kernel32!SetLastError  ß Lets set a breakpoint on last error to examine what is going on in the function calling it.

    0:007> g

    Breakpoint 1 hit

    eax=cccccccc ebx=00b93c48 ecx=00000000 edx=00b937a8 esi=00d9fcd0 edi=00d9fd9c

    eip=767913dd esp=00d9fcc8 ebp=00d9fd9c iopl=0         nv up ei pl zr na pe nc

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

    kernel32!SetLastError:

    767913dd 8bff            mov     edi,edi

    0:002> kv ß Get the call stack

    ChildEBP RetAddr 

    0:002> kv

    ChildEBP RetAddr  Args to Child             

    00d9fcc4 004116cb 00000057 00d9fe74 00000000 kernel32!SetLastError (FPO: [Non-Fpo])  ß 0x57 Invalid parameter error,  Why?

    00d9fd9c 00411657 00000000 00d9ff58 00000000 eatcpu!checkSomething+0x4b (FPO: [Non-Fpo]) (CONV: cdecl) [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 57]

    00d9fe74 004115a8 00000000 00000000 00000000 eatcpu!trySomething+0x27 (FPO: [Non-Fpo]) (CONV: cdecl) [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 45]

    00d9ff58 62bb4601 0017ff34 4f9f12e9 00000000 eatcpu!myThreadFunction+0x38 (FPO: [Non-Fpo]) (CONV: cdecl) [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 35]

    00d9ff94 62bb459c 00b937a8 00d9ffac 768019f1 MSVCR80D!_beginthread+0x221 (FPO: [Non-Fpo])

    00d9ffa0 768019f1 00b937a8 00d9ffec 77a2d109 MSVCR80D!_beginthread+0x1bc (FPO: [Non-Fpo])

    00d9ffac 77a2d109 00b93c48 00d926a6 00000000 kernel32!BaseThreadInitThunk+0xe (FPO: [Non-Fpo])

    00d9ffec 00000000 62bb4520 00b93c48 00000000 ntdll!_RtlUserThreadStart+0x23 (FPO: [Non-Fpo]) (CONV: stdcall) [d:\vistartm\base\ntos\rtl\rtlexec.c @ 2695]

    0:002> !error 00000057 ß double check, using !error, this will decode the error into a human readable string.

    Error code: (Win32) 0x57 (87) - The parameter is incorrect.

     

    0:002> uf checkSomething  ß lets disassemble the function calling SetLastError.

    eatcpu!checkSomething [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 49]:

       49 00411680 55              push    ebp

       49 00411681 8bec            mov     ebp,esp

       49 00411683 81ecc0000000    sub     esp,0C0h

       49 00411689 53              push    ebx

       49 0041168a 56              push    esi

       49 0041168b 57              push    edi

       49 0041168c 8dbd40ffffff    lea     edi,[ebp-0C0h]

       49 00411692 b930000000      mov     ecx,30h

       49 00411697 b8cccccccc      mov     eax,0CCCCCCCCh

       49 0041169c f3ab            rep stos dword ptr es:[edi]

       50 0041169e 837d0800        cmp     dword ptr [ebp+8],0 ß Check what our first parameter is on the stack, EBP+8 remember  PLUS == Parameters.  Note looking at the stack it’s 00000000     

       50 004116a2 741d            je      eatcpu!checkSomething+0x41 (004116c1ß if parameter 1 ones 0 we are going to jump to this addres, else we execute the following code. (WE JUMP) eatcpu!checkSomething+0x24 [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 52]:

       52 004116a4 8bf4            mov     esi,esp    ß The green would have been the good code path, non errant.

       52 004116a6 68fa000000      push    0FAh

       52 004116ab ff15a8814100    call    dword ptr [eatcpu!_imp__Sleep (004181a8)] ß Note we sleep or do some work other then eat CPU here if we are passed non ZERO

       52 004116b1 3bf4            cmp     esi,esp

       52 004116b3 e8a6faffff      call    eatcpu!ILT+345(__RTC_CheckEsp) (0041115e)

       53 004116b8 b801000000      mov     eax,1 ß We are setting EAX to 1, this means we have succeded

       53 004116bd eb15            jmp     eatcpu!checkSomething+0x54 (004116d4ß Now we jump to the clean up code for the fucntionn

     

    eatcpu!checkSomething+0x41 [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 57]:

       57 004116c1 8bf4            mov     esi,esp  ß This appears to be a failure case.  We did not get an expected parameter so we report an error and return zero.

       57 004116c3 6a57            push    57h ß Pusing error 0x57 on the stack, invalid parameter.

       57 004116c5 ff15a4814100    call    dword ptr [eatcpu!_imp__SetLastError (004181a4)] ß Our call to setlasterror

       57 004116cb 3bf4            cmp     esi,esp

       57 004116cd e88cfaffff      call    eatcpu!ILT+345(__RTC_CheckEsp) (0041115e)

       58 004116d2 33c0            xor     eax,eax  ß XORing eax with eax will make EAX Zero.  This is an error condition.

     

    eatcpu!checkSomething+0x54 [c:\source\eatcpu\eatcpu\eatcpu.cpp @ 60]:

       60 004116d4 5f              pop     edi

       60 004116d5 5e              pop     esi

       60 004116d6 5b              pop     ebx

       60 004116d7 81c4c0000000    add     esp,0C0h

       60 004116dd 3bec            cmp     ebp,esp

       60 004116df e87afaffff      call    eatcpu!ILT+345(__RTC_CheckEsp) (0041115e)

       60 004116e4 8be5            mov     esp,ebp

       60 004116e6 5d              pop     ebp

       60 004116e7 c3              ret

     

    The key thing that should be observed by this scenario is that when dealing with a high CPU condition there is often some problem at the lower level of some loop condition that prevents the proper execution of code from happening.  If you’re lucky the problem is reported by some error facility in the OS or the application.  In either case you can use the above technique for isolation.

     

    The following is the sample code for EATCPU.     

     

    // eatcpu.cpp : Defines the entry point for the console application.

    //

     

    #include "stdafx.h"

    #include <windows.h>

    #include <process.h>

     

    void myThreadFunction(void *);

    int doSomething(int);

    int trySomething(int);

    int checkSomething(int);

     

    int _tmain(int argc, _TCHAR* argv[])

    {

          int truevalue = 1;

          int falsevalue = 0;

          // let's start some threads.  These should represent worker threads in a process.  Some of them will do “valid work” one will fail to do so.

          _beginthread(myThreadFunction,12000,(void *)&truevalue);

          _beginthread(myThreadFunction,12000,(void *)&truevalue);

          _beginthread(myThreadFunction,12000,(void *)&truevalue);

          _beginthread(myThreadFunction,12000,(void *)&falsevalue );

          _beginthread(myThreadFunction,12000,(void *)&truevalue);

          _beginthread(myThreadFunction,12000,(void *)&truevalue);

     

          Sleep(10*60000);

          return 0;

    }

     

    void myThreadFunction(void *value)

    {

          int *localvalue = (int *)value;

     

          while(1)

          {

                trySomething(*localvalue);

          }

    }

    int doSomething(int value)

    {

          return trySomething(value);

     

    }

    int trySomething(int value)

    {

          return checkSomething(value);

     

    }

    int checkSomething(int value)

    {

          if(value)

          { // Make sure we have have some valid input parameter. 

            //We will pretend we are doing work, this could be anything , file I/O etc.

                Sleep(250);

                return TRUE;

          }

          else

          { // This is an error condition, this function expects an NON Zero parameter and will report ZERO as an invalid parameter.

     

                SetLastError(ERROR_INVALID_PARAMETER);

                return FALSE;

          }

    }

     

     

     

  • Ntdebugging Blog

    !Search to the Rescue!

    • 6 Comments

    My name is Trey Nash and I am an Escalation Engineer on the Core OS team.  My experience is as a software developer, and therefore, my blog posts tend to be slanted in the direction of helping developers during the feature development, testing, and the support phases.

    Windbg is definitely a feature-rich debugger.  Sometimes, reading the debugger help during idle time can provide some great insight into the capabilities of the debugger.  However, the debugger help comes up short when you ask questions such as, “command huh-huh sure is cool, but when would I ever want to do that?!?”  Besides, if you’re caught reading the windbg help in your spare time, you may be on the receiving end of some ridicule form those in your social circle.

    In this post, I would like to speak a bit about the !search command, among others,  and when you would want to use it.  Additionally, I’ll be demonstrating some related techniques germane to when you would use !search in the first place.

    Not long ago, I was working with a dump from a machine that was hung and it was my job to find out why.  After applying many of the techniques in our hang dump blog post, I discovered that there was a thread in particular that was stuck, which I show below:

    0: kd> !thread fe016330
    THREAD fe016330  Cid 0004.02e0  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
        fcf1a698  SynchronizationEvent
        fe0163a8  NotificationTimer
    IRP List:
       
    fcb47650
    : (0006,01d8) Flags: 00000404  Mdl: 00000000
    Not impersonating
    DeviceMap                 e18008e8
    Owning Process            fe790648       Image:         System
    Attached Process          N/A            Image:         N/A
    Wait Start TickCount      75337682       Ticks: 145 (0:00:00:02.265)
    Context Switch Count      31848752            
    UserTime                  00:00:00.000
    KernelTime               
    00:25:38.000
    Start Address Treyresearch (0xf45629e0)
    Stack Init f50e1000 Current f50e05e8 Base f50e1000 Limit f50de000 Call 0
    Priority 15 BasePriority 15 PriorityDecrement 0
    ChildEBP RetAddr  Args to Child             
    f50e0600 e103d5b1 fe016330 fe0163d8 00000000 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
    f50e062c e103df9e fe016330 fd0321f8 00000000 nt!KiSwapThread+0x2e5 (FPO: [0,7,0])
    f50e0674 e101e05b fcf1a698 0000001b 00000000 nt!KeWaitForSingleObject+0x346 (FPO: [5,13,4])
    f50e06b0 e102e00a e3faf6e0 f50e0900 00000000 nt!ExpWaitForResource+0xd5 (FPO: [0,5,4])
    f50e06d0 f5a988cb
    fd0321f8 00000001 f50e08e4 nt!ExAcquireResourceExclusiveLite
    +0x8d (FPO: [2,3,0])
    f50e06e0 f5ad81c4 f50e0900 e3faf6e0 00000001
    Ntfs!NtfsAcquirePagingResourceExclusive
    +0x20 (FPO: [3,0,0])
    f50e08e4 f5ad8909 f50e0900 fcb47650 fdcc3020 Ntfs!NtfsCommonCleanup+0x193 (FPO: [SEH])
    f50e0a54 e1040153 fe00d718
    fcb47650 fcb47650 Ntfs!NtfsFsdCleanup
    +0xcf (FPO: [SEH])
    f50e0a68 f5b4fd28 fddbc818 fe6d1a28 00000000 nt!IofCallDriver+0x45 (FPO: [0,0,4])
    f50e0a94 e1040153 fdcc3020 fcb47650 fcb47650 fltmgr!FltpDispatch+0x152 (FPO: [2,6,0])
    f50e0aa8 f5b4fb25 fdde0cb0 fcb47650 fdd8dc18 nt!IofCallDriver+0x45 (FPO: [0,0,4])
    f50e0acc f5b4fcf5 f50e0aec fdde0cb0 00000000 fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x20b (FPO: [3,4,4])
    f50e0b04 e1040153 fdde0cb0 fcb47650 fcb47650 fltmgr!FltpDispatch+0x11f (FPO: [2,6,0])
    f50e0b18 e112ec0a fdfd9bd8 fe774730 fdfd9bf0 nt!IofCallDriver+0x45 (FPO: [0,0,4])
    f50e0b48 e112b6af fe790648 fdde0cb0 00010003 nt!IopCloseFile+0x2ae (FPO: [5,7,0])
    f50e0b78 e112b852 fe790648 00000001 fe774730 nt!ObpDecrementHandleCount+0xcc (FPO: [4,2,4])
    f50e0ba0 e112b776 e1802e48 fdfd9bf0 00006e54 nt!ObpCloseHandleTableEntry+0x131 (FPO: [5,1,0])
    f50e0be4 e112b7c1 00006e54 00000000 f50e0c00 nt!ObpCloseHandle+0x82 (FPO: [2,7,4])
    f50e0bf4 e1033bdf 00006e54 f50e0cfc e103b00c
    nt!NtClose
    +0x1b (FPO: [1,0,0])
    f50e0bf4 e103b00c 00006e54 f50e0cfc e103b00c nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ f50e0c00)
    f50e0c70 f4562119 00006e54 00030000 00000068 nt!ZwClose+0x11 (FPO: [1,0,0])
    WARNING: Stack unwind information not available. Following frames may be wrong.
    f50e0cfc f456229f f50e0d34 f50e0d2c f4577f50 Treyresearch+0x11119
    f50e0d38 f45626f9 fe016330 fc825368 00000000 Treyresearch+0x1129f
    f50e0d70 f45629ae f1ed8000 00002000 00000000 Treyresearch+0x116f9
    f50e0d90 f4562ba3 fc825318 fde59b38 00000003 Treyresearch+0x119ae
    f50e0dac e1120833 f4577e20 00000000 00000000 Treyresearch+0x11ba3
    f50e0ddc e103fe9f f45629e0 f4577e20 00000000 nt!PspSystemThreadStartup+0x2e (FPO: [SEH])
    00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

    Note:    Eagle-eye readers may have noticed that the debugger states every frame in the above thread uses frame pointer optimization (FPO).  This is a bug in version 6.11.0001.402 of the debugger.

    I have highlighted the interesting bits above.  It seems that this thread is some sort of worker thread, probably created by the Treyresearch driver.  It is doing some work that includes closing a particular file.  In the process of closing the file, NTFS wants to acquire the paging resource for this particular file, and that is where this thread gets stuck.

    What is the paging resource?  Many file systems have a per-file lock that one acquires when performing paging I/O such that other destabilizing activity cannot occur at the same time as a paging operation.  The paging resource for the file is this lock.

    To further illustrate the paging resource, let’s check out the file in question.  One handy things that you can do is follow the stack down to where you see the most recent call to nt!IofCallDriver.  You can see in the MSDN documentation that IoCallDriver accepts two parameters, a DEVICE_OBJECT* and an IRP*.  However, nt!IofCallDriver is a fastcall function, so you cannot find its parameters on the stack.  But since you know that nt!IofCallDriver is calling a driver dispatch routine, and since driver dispatch routines have the same prototype as IoCallDriver, you can easily find the IRP in question which I have highlighted in the Ntfs!NtfsFsdCleanup frame of the  thread’s stack above and dumped out below:

    0: kd> !irp fcb47650
    Irp is active with 10 stacks 10 is current (= 0xfcb47804)
     No Mdl: No System Buffer: Thread fe016330:  Irp stack trace. 
         cmd  flg cl Device   File     Completion-Context
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
    >[ 12, 0]   0  0 fe00d718
    fdfd9bf0
    00000000-00000000   
                  \FileSystem\Ntfs
                         Args: 00000000 00000000 00000000 00000000

    And from the IRP above, we can find the real file that the thread above is trying to acquire the paging lock for:

    0: kd> !fileobj fdfd9bf0

    \Program Files\Treyresearch\Treyresearch.data

    Device Object: 0xfe6da738   \Driver\Ftdisk
    Vpb: 0xfe791818
    Access: Read Write Delete SharedRead SharedWrite SharedDelete

    Flags:  0x43062
           Synchronous IO
           Sequential Only
           Cache Supported
           Modified
           Size Changed
           Handle Created

    File Object is currently busy and has 0 waiters.

    FsContext:
    0xe3faf7a8      FsContext2: 0xe3faf8f0
    Private Cache Map: 0xfccf1fa0
    CurrentByteOffset: 6400164
    Cache Data:
      Section Object Pointers: fc956f3c
      Shared Cache Map: fccf1ec8         File Offset: 6400164
      Vacb: fe77bd80
      Your data is at: cbe80164

    The file object contains two fields named FsContext and FsContext2 shown above.  These fields are for the file system to store file system specific information.  Most file systems would store the paging resource in these context fields somewhere.  For example, NTFS uses FsContext to hold the stream control block (SCB) and you can surmise that somewhere down in the SCB is where NTFS stores the paging resource. (It’s actually more complicated than that, but that’s good enough for sake of this discussion)

    Now, let’s take a look at the paging resource itself.  You can see from the documentation of ExAcquireResourceExclusiveLite, the first parameter is an ERESOURCE and I have highlighted it in our thread stack above.  Given that, we can use the !locks command to get a better idea of what’s going on:

    0: kd> !locks -v fd0321f8

    Resource @ 0xfd0321f8    Shared 1 owning threads
        Contention Count = 2
        NumberOfSharedWaiters = 1
        NumberOfExclusiveWaiters = 1
         Threads:
    fe77f1e0-07<*>     
    ß This thread is the owner

         THREAD fe77f1e0  Cid 0004.0064  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
             fc825320  NotificationEvent
         Not impersonating
         DeviceMap                 e18008e8
         Owning Process            fe790648       Image:         System
         Attached Process          fced2d88       Image:         store.exe
         Wait Start TickCount      75281842       Ticks: 55985 (0:00:14:34.765)
         Context Switch Count      4440231            
         UserTime                  00:00:00.000
         KernelTime                00:01:51.171
         Start Address nt!MiMappedPageWriter (0xe101962c)
         Stack Init f6137000 Current f61366ac Base f6137000 Limit f6134000 Call 0
         Priority 17 BasePriority 8 PriorityDecrement 0
         ChildEBP RetAddr 
         f61366c4 e103d5b1 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
         f61366f0 e103df9e nt!KiSwapThread+0x2e5 (FPO: [0,7,0])
         f6136738 f4562e28 nt!KeWaitForSingleObject+0x346 (FPO: [5,13,4])
    WARNING: Stack unwind information not available. Following frames may be wrong.
         f6136760 f4563229 Treyresearch+0x11e28
         f6136788 f4559d8f Treyresearch+0x12229
         f61367e4 f4570b95 Treyresearch+0x8d8f
         f613684c f4570e39 Treyresearch+0x1fb95
         f6136898 f4570f4b Treyresearch+0x1fe39
         f61368c4 f5b4cb73 Treyresearch+0x1ff4b
         f613692c f5b4efc2 fltmgr!FltpPerformPostCallbacks+0x1c5 (FPO: [1,17,4])
         f6136940 f5b4f4f1 fltmgr!FltpProcessIoCompletion+0x10 (FPO: [1,0,0])
         f6136950 f5b4fb83 fltmgr!FltpPassThroughCompletion+0x89 (FPO: [3,0,4])
         f6136980 f5b4fcf5 fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x269 (FPO: [3,4,4])
         f61369b8 e1040153 fltmgr!FltpDispatch+0x11f (FPO: [2,6,0])
         f61369cc f452b2f8 nt!IofCallDriver+0x45 (FPO: [0,0,4])
         f6136a18 f452b6d3 exifs!NtSystemWrite+0x1ff (FPO: [Non-Fpo])
         f6136ab0 f452ae1d exifs!IfsInternalWrite+0x1a0 (FPO: [Non-Fpo])
         f6136b24 f4549e02 exifs!MRxIfsWrite+0x333 (FPO: [Non-Fpo])
         f6136b44 f4541a8e exifs!RxLowIoSubmit+0x180 (FPO: [Uses EBP] [2,2,4])
         f6136b54 f45427ed exifs!RxLowIoWriteShell+0x2e (FPO: [1,0,1])
         f6136c64 f452fbe3 exifs!RxCommonWrite+0xcc1 (FPO: [Non-Fpo])
         f6136cf8 f453dffd exifs!RxFsdCommonDispatch+0x2c4 (FPO: [Non-Fpo])
         f6136d24 f452439a exifs!RxFsdDispatch+0x93 (FPO: [Non-Fpo])
         f6136d40 e1040153 exifs!MRxIfsFsdDispatch+0x6c (FPO: [Non-Fpo])
         f6136d54 e101c5b4 nt!IofCallDriver+0x45 (FPO: [0,0,4])
         f6136d68 e101971d nt!IoAsynchronousPageWrite+0xd0 (FPO: [8,0,4])
         f6136dac e1120833
    nt!MiMappedPageWriter
    +0x12e (FPO: [1,4,0])
         f6136ddc e103fe9f nt!PspSystemThreadStartup+0x2e (FPO: [SEH])
         00000000 00000000 nt!KiThreadStartup+0x16

    fe78eb40-01   

         THREAD fe78eb40  Cid 0004.001c  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
             fcea3890  Semaphore Limit 0x7fffffff
             fe78ebb8  NotificationTimer
         Not impersonating
         DeviceMap                 e18008e8
         Owning Process            fe790648       Image:         System
         Attached Process          N/A            Image:         N/A
         Wait Start TickCount      75337718       Ticks: 109 (0:00:00:01.703)
         Context Switch Count      3480314            
         UserTime                  00:00:00.000
         KernelTime                00:01:35.875
         Start Address nt!ExpWorkerThread (0xe102da4b)
         Stack Init f60ef000 Current f60eebf0 Base f60ef000 Limit f60ec000 Call 0
         Priority 14 BasePriority 13 PriorityDecrement 1
         ChildEBP RetAddr 
         f60eec08 e103d5b1 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
         f60eec34 e103df9e nt!KiSwapThread+0x2e5 (FPO: [0,7,0])
         f60eec7c e101e05b nt!KeWaitForSingleObject+0x346 (FPO: [5,13,4])
         f60eecb8 e1024ba8 nt!ExpWaitForResource+0xd5 (FPO: [0,5,4])
         f60eecd8 f5a98915 nt!ExAcquireResourceSharedLite+0xf5 (FPO: [2,3,4])
         f60eece8 f5ae198a Ntfs!NtfsAcquirePagingResourceShared+0x20 (FPO: [3,0,0])
         f60eed04 e1044997 Ntfs!NtfsAcquireScbForLazyWrite+0x7a (FPO: [2,0,0])
         f60eed40 e104328e nt!CcWriteBehind+0x27 (FPO: [0,8,4])
         f60eed80 e102db08 nt!CcWorkerThread+0x15a (FPO: [SEH])
         f60eedac e1120833 nt!ExpWorkerThread+0xeb (FPO: [1,5,0])
         f60eeddc e103fe9f nt!PspSystemThreadStartup+0x2e (FPO: [SEH])
         00000000 00000000 nt!KiThreadStartup+0x16

         Threads Waiting On Exclusive Access:

                  fe016330      

    Now this is some juicy output.  I used the –v option to also expand some of the threads related to this lock.  The owner thread is the one with the asterisk (*) next to it and you can see from the expanded thread listing and based on the fact that the function at the bottom of the stack is nt!MiMappedPageWriter, that the thread in question is the mapped page writer.  This thread is a system thread that periodically sweeps through a list of dirty pages flushing them out to disk.  Interestingly, the mapped page writer has acquired the ERESOURCE seven times.  That is shown by the -07 next to the owner thread in the above output.  The second thread is waiting for shared access and it is a system file cache thread.  And finally, the third thread is our initial hung thread that is waiting on exclusive access.

    As a sanity check, let’s make sure that the ERESOURCE and the file in question are related.  Previously, I stated that in the NTFS file system the FsContext field of the file object contains an SCB.  Let’s pass that pointer to !pool and get some more information about it:

    0: kd> !pool 0xe3faf7a8 2
    Pool page e3faf7a8 region is Paged pool
    *e3faf6d8 size:  330 previous size:   20  (Allocated) *Ntff
                  Pooltag Ntff : FCB_DATA, Binary : ntfs.sys

    Now, we can use the search command (s), to search the pool memory above and see if our ERESOURCE is in there.  If so, that would satisfy our sanity check:

    0: kd> s -d e3faf6d8 L 330/4 fd0321f8
    e3faf72c  fd0321f8 0c9013aa 01c9969b 42002f46  .!..........F/.B
    e3faf7b4  fd0321f8 06410000 00000000 06400164  .!....A.....d.@.

    Now that we are satisfied that we have matched up the ERESOURCE with the file that owns it, let’s move on.  At first glance of the mapped writer thread, it looks like the offending entity is exifs.  After all, it’s the most interesting component on the mapped page writer stack.  But don’t be fooled.  What you see in the mapped page writer stack is a snapshot of what it was doing when the dump was taken, and that’s not necessarily the work that caused things to go bad in the first place.  Even though exifs is a file system, it is not NTFS.  And we know an NTFS file’s paging resource is locked.  Keep in mind that the mapped page writer is processing a list.  So the items on the list that have caused the contention may have long been taken off the list and processed.

    So what do you do?  Unfortunately, the badness happened some time ago.  We don’t have a stack to look at to show who did this and when.  But what we can do is perform a search of memory to see if there are any references to the ERESOURCE elsewhere in memory.  If we find some hits, maybe they will shed some more light on what is going on.  So, let’s go ahead and do that:

    0: kd> !search fd0321f8
    Searching PFNs in range 0000000B - 000DFFF9 for [FFFFFFFFFD0321F8 - FFFFFFFFFD0321F8]

    Pfn      Offset   Hit      Va       Pte     
    - - - - - - - - - - - - - - - - - - - - - - - - - - -
    00007AB7 000004E8 FD0321F8 FCAB74E8 C03F2ADC
           fcab74e0+0x8     : Ntfr  -- ERESOURCE
    00007CDF 00000950 FD0321F8 FCCDF950 C03F337C
           fccdf938+0x18    : NpFc  -- CCB, client control block - Process: fdd70248
    0000803A 0000022C FD03A1F8 FD03A22C C03F40E8
           fd03a220+0xc     : Vad   -- Mm virtual address descriptors
    0000977F 0000003C FD0321F8
    FE77F03C
    C03F9DFC
           fe77f000+0x3c    :
    MmWe  -- Work entries for writing out modified filesystem pages.
    0000977F 00000514 FD0321F8 FE77F514
    C03F9DFC
           fe77f4d8+0x3c    :
    MmWe  -- Work entries for writing out modified filesystem pages.
    0000977F 000005BC FD0321F8 FE77F5BC
    C03F9DFC
           fe77f580+0x3c    :
    MmWe  -- Work entries for writing out modified filesystem pages.
    0000977F 00000904 FD0321F8 FE77F904
    C03F9DFC
           fe77f8c8+0x3c    :
    MmWe  -- Work entries for writing out modified filesystem pages.
    0000977F 00000BA4 FD0321F8 FE77FBA4
    C03F9DFC
           fe77fb68+0x3c    :
    MmWe  -- Work entries for writing out modified filesystem pages.
    0000978A 00000324 FD0321F8 FE78A324
    C03F9E28
           fe78a2e8+0x3c    :
    MmWe  -- Work entries for writing out modified filesystem pages.
    0000978A 0000051C FD0321F8 FE78A51C
    C03F9E28
           fe78a4e0+0x3c    :
    MmWe  -- Work entries for writing out modified filesystem pages.
    00060B7B 0000072C FD0321F8 E3FAF72C C038FEBC
           e3faf6d8+0x54    : Ntff  -- FCB_DATA
    00060B7B 000007B4 FD0321F8 E3FAF7B4 C038FEBC
           e3faf6d8+0xdc    : Ntff  -- FCB_DATA
    000D9653 00000638 FD0321F8 F50E0638 C03D4380
    000D9653 00000694 FD0321F8 F50E0694 C03D4380
    000D9653 000006D8 FD0321F8 F50E06D8 C03D4380
    000DE415 0000054C F50321F8 F503254C C03D40C8
    000DFBF4 00000C40 FD0321F8 F60EEC40 C03D83B8
    000DFBF4 00000C9C FD0321F8 F60EEC9C C03D83B8
    000DFBF4 00000CE0 FD0321F8 F60EECE0 C03D83B8
    Search done.

    One thing to note is that there are some hits that are not exactly what we were looking for.  That’s because !search also looks for values that are one bit off from what you requested.  Check out the help for how you can adjust this behavior.  Also, !search performs some extra work along the way.  If it notices that the virtual address found is in the pool, it displays information about that pool entry.

    Do you spot the curiosity?  Remember that the ERESOURCE had been acquired seven times.  Correspondingly, there are seven hits in the !search list with the MmWe tag!  And not surprisingly, the description of that tag pulled from pooltag.txt file in the triage directory where the debugger is installed reveals that these are paging work entries.  Now we’re on to something.

    Note:    Incidentally, if you want to determine where a virtual address in the list above resides, you can always pass it to !address.  The addresses at the end of the !seach output are often addresses on some thread’s stack.  If you pass those addresses to !thread, it is smart enough to find the thread that is associated with that stack and display it for you.

     “OK, but how do I find the real culprit?”, you then say.  Well, you have to continue to dig with what you have.  Unfortunately, the contents of the pool entries with MmWe tags are not documented, although, we definitely know what they are.  Let’s take a look at one of them using !pool:

    0: kd> !pool FE77F03C
    Pool page fe77f03c region is Nonpaged pool
    *
    fe77f000 size:   a8
    previous size:    0  (Allocated) *MmWe
                  Pooltag MmWe : Work entries for writing out modified filesystem pages., Binary : nt!mm

    Now, we see where the pool entry starts and how big the entry is.  So, let’s take a look at the contents of the memory:

    0: kd> dps fe77f000 L a8/@$ptrsize
    fe77f000  0a150000
    fe77f004  65576d4d
    fe77f008  fe78a4e8
    fe77f00c  e10b3af0 nt!MmMappedPageWriterList
    fe77f010  06140000
    fe77f014  00000000
    fe77f018  06150000
    fe77f01c  00000000
    fe77f020  fcc20788
    fe77f024  00000000
    fe77f028  e10b3f20 nt!MmMappedFileHeader
    fe77f02c  00000000
    fe77f030  00000000
    fe77f034  fdfd9bf0
    fe77f038  fdc6f008
    fe77f03c  fd0321f8
    fe77f040  00000000
    fe77f044  00000000
    fe77f048  00000000
    fe77f04c  0002005c
    fe77f050  00000000
    fe77f054  f1d20000
    fe77f058  00000000
    fe77f05c  00010000
    fe77f060  00000000
    fe77f064  0007036c
    fe77f068  000cb59d
    fe77f06c  000a97fe
    fe77f070  0000d7ef
    fe77f074  00021c90
    fe77f078  0005d6b1
    fe77f07c  000a5642
    fe77f080  0004d5c3
    fe77f084  000ae354
    fe77f088  00038249
    fe77f08c  000509ea
    fe77f090  0009c915
    fe77f094  00018dd6
    fe77f098  000b94d7
    fe77f09c  0006ca58
    fe77f0a0  00091e29
    fe77f0a4  00000000

    I used the dps command so that it would check to see if any of the values matched to any known symbols.  As you can see, there are a couple of symbols in there.  Notice that I divided the size of the block by the pseudo register $ptrsize as well.  The symbols that dps found validate that this block of memory is associated with the mapped page writer.

    You may also ask yourself, “are any of these values pointers to other pool blocks?”  If you wanted to know that, you could iterate over each one of them passing them to !pool or !address.  That sounds tedious to do manually.  But thankfully, the debugger has some nice command tokens such as .foreach that make this a breeze.  If you want to pass each of the above values to !pool, you can perform the following in the debugger:

    .foreach /pS 1 /ps 1 ( value { dp /c 1 fe77f000 L a8/@$ptrsize } ) { .if( value != 0 ) {.printf "**** %p ****\n", ${value}; !pool ${value} 0x2} }

    The address highlighted above is the address of the pool block revealed by the previous !pool command.  a8 is the size of the block in bytes and since dp lists the memory in units of pointer size, I divide a8 by $ptrsize.

    I won’t show the full output here, because it’s rather verbose.  But I have duplicated the output from the dps command above with added pool tags next to items that are pool entries:

    0: kd> dps fe77f000 L a8/@$ptrsize
    fe77f000  0a150000
    fe77f004  65576d4d
    fe77f008  fe78a4e8   Pooltag MmWe : Work entries for writing out modified filesystem pages., Binary : nt!mm
    fe77f00c  e10b3af0 nt!MmMappedPageWriterList
    fe77f010  06140000
    fe77f014  00000000
    fe77f018  06150000
    fe77f01c  00000000
    fe77f020 
    fcc20788   Pooltag Irp  : Io, IRP packets
    fe77f024  00000000
    fe77f028  e10b3f20 nt!MmMappedFileHeader
    fe77f02c  00000000
    fe77f030  00000000
    fe77f034 
    fdfd9bf0   Pooltag File : File objects
    fe77f038  fdc6f008   Pooltag MmCa : Mm control areas for mapped files, Binary : nt!mm
    fe77f03c 
    fd0321f8
       Pooltag Ntfr : ERESOURCE, Binary : ntfs.sys
    fe77f040  00000000
    fe77f044  00000000
    fe77f048  00000000
    fe77f04c  0002005c

    <snip>

     

    Sure enough, the file object above is identical to the file we identified earlier on as the one that the worker thread was attempting to close a handle to.  Also, you can see that our ERESOURCE is in there as well.  And even more, now we have an IRP that may reveal even more information.  Let’s see:

    0: kd> !irp fcc20788 1
    Irp is active with 10 stacks 12 is current (= 00000000)
     Mdl=fe77f048: No System Buffer: Thread fd089e6c: 
    Irp is completed
    .  Pending has been returned
    Flags = 00000003
    ThreadListEntry.Flink = fcc20798
    ThreadListEntry.Blink = fcc20798
    IoStatus.Status = 00000000
    IoStatus.Information = 00010000

    RequestorMode = 00000000
    Cancel = 00
    CancelIrql = 0
    ApcEnvironment = 00
    UserIosb = fe77f018
    UserEvent = 00000000
    Overlay.AsynchronousParameters.UserApcRoutine = e101c95b
    Overlay.AsynchronousParameters.UserApcContext = fe77f008
    Overlay.AllocationSize = 00000000 - 00000000
    CancelRoutine = 00000000   
    UserBuffer = 00000000
    &Tail.Overlay.DeviceQueueEntry = fcc207c8
    Tail.Overlay.Thread = fd089e6c
    Tail.Overlay.AuxiliaryBuffer = e101cb86
    Tail.Overlay.ListEntry.Flink = 00000000
    Tail.Overlay.ListEntry.Blink = 00000000
    Tail.Overlay.CurrentStackLocation = 00000000
    Tail.Overlay.OriginalFileObject = 00000000
    Tail.Apc = 00300012
    Tail.CompletionKey = 00300012
         cmd  flg cl Device   File     Completion-Context
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  0, 0]   0  0 00000000 00000000 00000000-00000000   

                         Args: 00000000 00000000 00000000 00000000
     [  4, 0]   0  0 fe755ab8 00000000 f5ce857e-fe709df8   
                  \Driver\Disk  PartMgr!PmIoCompletion
                         Args: 00000000 00000000 00000000 0000000c
     [  4, 0]   0  0 fe709df8 00000000 f5c16558-fe6da7f0   
                  \Driver\PartMgr     ftdisk!FtpRefCountCompletionRoutine
                         Args: 00000000 00000000 00000000 0000000c
     [  4, 0]   0  0 fe6da738 00000000 f5bc0638-fe6d6a80   
                  \Driver\Ftdisk      volsnap!VspRefCountCompletionRoutine
                         Args: 00000000 00000000 00000000 0000000c
     [  4, 0]   0  0 fe6d69c8 00000000 f5d0af28-00000000   
                  \Driver\VolSnap     vsp
                         Args: 00000000 00000000 00000000 0000000c
     [  4, 0]   0  0 fe6d66c0 00000000 f5a9351c-fde38cd0   
                  \Driver\VSP   Ntfs!NtfsSingleAsyncCompletionRoutine
                         Args: 00000000 00000000 00000000 0000000c
     [  4, 0]   0  0 fe00d718 00000000 00000000-00000000   
                  \FileSystem\Ntfs
                         Args: 00000000 00000000 00000000 00000000

    What is apparent from looking at this IRP is that it is flagged as completed.  Moreover, the information in the IoStatus fields looks to be relevant as well.  But after studying the situation a little deeper, it appeared that the completion routine had never been fired.  We can find out more about the completion routine by dumping out the Tail.Apc portion of the IRP as shown below:

    0: kd> dt nt!_IRP fcc20788 Tail.Apc.
       +0x040 Tail      :
          +0x000 Apc       :
             +0x000 Type      : 0x12 ''
             +0x001 SpareByte0 : 0 ''
             +0x002 Size      : 0x30 '0'
             +0x003 SpareByte1 : 0 ''
             +0x004 SpareLong0 : 0
             +0x008 Thread    :
    0xfe77f1e0
    _KTHREAD
             +0x00c ApcListEntry : _LIST_ENTRY [ 0xfcde8ce4 - 0xfd089e6c ]
             +0x014
    KernelRoutine : 0xe101cb86           void  nt!IopCompletePageWrite+0
             +0x018 RundownRoutine : (null)
             +0x01c NormalRoutine : (null)
             +0x020 NormalContext : (null)
             +0x024 SystemArgument1 : (null)
             +0x028 SystemArgument2 : (null)
             +0x02c ApcStateIndex : 0 ''
             +0x02d ApcMode   : 0 ''
             +0x02e
    Inserted  : 0x1 ''

    Recall from the rules of IRP processing on Windows that IRPS like these have their completion routines called within the thread context that initiated the I/O.  As you can see above, that thread is the same thread that is running nt!MiMappedPageWriter.  Moreover, the Inserted flag is set above, which means that the APC has been placed in the APC queue for the thread.  Deductive reasoning would imply that if the completion routine has not run, then the APC has not been delivered.  And the APC will not be delivered if normal kernel mode APCs are disabled at the moment.  So, let’s check on that by looking in the nt!KTHREAD structure:

    0: kd> dt nt!_KTHREAD 0xfe77f1e0 KernelApcDisable
       +0x070 KernelApcDisable :
    -2

    Sure enough, kernel APCs are disabled for this thread at the moment.  How can that be?  Well, there are several ways to disable normal kernel APC delivery and it often involves either directly or indirectly entering a critical or guarded region.  Critical regions are entered directly via KeEnterCriticalRegion and guarded regions are entered via KeEnterGuardedRegion.  However, there are several means of indirectly entering critical regions including FsRtlEnterFileSystem.    Additionally, holding a mutex object automatically places the holder in a critical region.

    Therefore, the root cause in this case was that the file system drivers appear to have put the thread into a state where it cannot receive APCs and, therefore, I/O initiated on that thread could not be completed.  The APCs build up in the queue so that they can be delivered when kernel APC delivery is re-enabled.  Incidentally, the documentation for FsRtlEnterFileSystem states that file system filter drivers should never disable normal kernel APCs across calls to IoCallDriver.

    Conclusion

    Many times, when it looks like you are hitting up against a brick wall in determining what went wrong in a dump, you can get a lot further than you initially expect with a little bit of intuition and the right tools.  Of course, this intuition will grow as you become more and more familiar with the Windows operating system internals, or whatever platform you work on.  Using !search to search physical memory in the dump file can help find references (a.k.a pointers) to objects in hard to find places.  Additionally, pool tag information along with the helpful text in the pooltag.txt file displayed by !pool goes a long way when it comes to figuring out what a particular pool block is used for.  Armed with all of these tools, you can always get farther than one may initially expect.

    Happy debugging everyone!

    "The example companies, organizations, products, domain names, e-mail addresses, logos, people, places, and events depicted herein are fictitious.  No association with any real company, organization, product, domain name, email address, logo, person, places, or events is intended or should be inferred."

     

    Share this post :
  • Ntdebugging Blog

    Critical Device Database TIP

    • 6 Comments

    On a fairly regular basis, Bob Golding, our resident GES storage guru, sends out debugging tips to our group. We thought our blog readers would find value in these tips so we’re posting one here. Let us know what you think of the nugget.

    Thanks,

    Ron

    Introduction

    Hi everyone, Bob here.  Today I thought we’d have a little discussion about the Critical Device Database (CDDB) in the registry and an issue that can be caused when a device is not contained there.  This database stores configuration data for new devices that must be installed and started before the Windows components that normally install devices have been started.  The idea behind the critical device database is to allow the installation of devices without using user mode plug-and-play manager.   If a device is determined to be new, this database is queried to see if the information needed to install it are present. 

    What was the issue?

    A customer was getting a Stop 0x7B (Inaccessible_Boot_Device) after they installed a BIOS update.  Further investigation via the debugger using the !devnode command showed the following issue with a few devices:

             DevNode 0x8631f008 for PDO 0x8631f8e0

               InstancePath is "PCI\VEN_15B3&DEV_5A44&SUBSYS_5A4415B3&REV_A1\6&38f4f1f2&0&00080310"

               State = DeviceNodeInitialized (0x302)

               Previous State = DeviceNodeUninitialized (0x301)

               Problem = CM_PROB_NOT_CONFIGURED

    The above device is a bridge, and according to the definition of CM_PROB_NOT_CONFIGURED, it does not have a ConfigFlags registry entry.  I saw that this same problem occurred with a few bridges.  If the bridge cannot be enumerated, devices on the bridge will not be discovered either.  The Instance ID is used to look up the particulars such as driver name and class in the HKLM\System\CurrentControlSet\ENUM key in the registry.  What happened here is the lookup failed and the system thought it was a new device.  Since based on the device class this device was needed for boot, a Stop 0x7B occurred.

    What caused the issue?

    When the BIOS was updated the Instance ID included the version number of the bridge.  The update increased the version number, so the Instance ID was changed.

           DevNode 0x8635ca40 for PDO 0x8634c4a8

              InstancePath is "PCI\VEN_8086&DEV_1A38&SUBSYS_02DD1014&REV_B1\3&11583659&0&40"

              State = DeviceNodeInitialized (0x302)

              Previous State = DeviceNodeUninitialized (0x301)

              Problem = CM_PROB_NOT_CONFIGURED

    Looking at the registry data we could see:

    PCI\VEN_8086&DEV_1A38&SUBSYS_02DD1014&REV_93

    So a revision change caused the issue.

    What stops this from happening?

    Certain devices in the system are required for boot.  The device class determines if the device is in the boot device family.  If so, the hardware ID is written to the CDDB in the registry, so that if the device is determined to be new, it can be found there during boot.

    Below is an example of a bridge entry.  The contents of the pci#ven_8086&dev_244e contain the driver and the class.  This is enough to get the device started for boot.  The user mode PNP manager will complete the installation.

    HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\CriticalDeviceDatabase\pci#ven_8086&dev_244e

    How come this bridge was not there?

    When the INF was run, the device class was set to “unknown” class, so the OS did not know to write the information in the CDDB.  

    What was done to correct the problem?

    The BIOS update was temporarily reverted, and then the correct install package was found with the correct INF that has the bridges defined as a system device.  The device was re-installed (pre-update) so the device could be written properly in the CDDB, then the BIOS update was reapplied without a problem.

     

     

Page 5 of 23 (230 items) «34567»