• Ntdebugging Blog

    Debugging a bluescreen at home

    • 15 Comments

     

    Hi, my name is Chad. I work as an escalation engineer for Microsoft’s OEM support team.

     

    A while back, I encountered an interesting crash on one of my computers at home, and I thought I’d post about how I debugged it.

     

    This particular machine had been humming along quite happily for some time, but one day while I was scanning some photos, it bluescreened. Naturally, I hoped it was just a fluke, but after it happened a few more times while doing the same thing, I decided to debug it.

     

    Ordinarily, if a machine crashes when performing a specific activity, like scanning photos, my first inclination would be to suspect a bug in one of the drivers involved in that activity, like the scanner driver or the USB driver. But in this case, I had been using this scanner for a long time, with the same drivers, and never had this problem, so this sudden crashing was kind of mysterious.

     

    Let's see what we can tell from the dump!

     

    The first order of business when looking at a crash dump is the !analyze -v command. I've trimmed some of it here for brevity, but it goes something like this:

     

    kd> !analyze -v

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

    *                                                                             *

    *                        Bugcheck Analysis                                    *

    *                                                                             *

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

     

    KERNEL_MODE_EXCEPTION_NOT_HANDLED (8e)

    This is a very common bugcheck.  Usually the exception address pinpoints

    the driver/function that caused the problem.  Always note this address

    as well as the link date of the driver/image that contains this address.

    Some common problems are exception code 0x80000003.  This means a hard

    coded breakpoint or assertion was hit, but this system was booted

    /NODEBUG.  This is not supposed to happen as developers should never have

    hardcoded breakpoints in retail code, but ...

    If this happens, make sure a debugger gets connected, and the

    system is booted /DEBUG.  This will let us see why this breakpoint is

    happening.

    Arguments:

    Arg1: c0000005, The exception code that was not handled

    Arg2: 8738e300, The address that the exception occurred at

    Arg3: b9b3dc7c, Trap Frame

    Arg4: 00000000

     

    Debugging Details:

    ------------------

     

     

    EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at "0x%08lx" referenced memory at "0x%08lx". The memory could not be "%s".

     

    FAULTING_IP:

    +ffffffff8738e300

    8738e300 0000             add     [eax],al

     

    TRAP_FRAME:  b9b3dc7c -- (.trap ffffffffb9b3dc7c)

    ErrCode = 00000002

    eax=00000001 ebx=bc514c68 ecx=0001065e edx=bc510000 esi=00000955 edi=b9b3dd64

    eip=8738e300 esp=b9b3dcf0 ebp=b9b3dd08 iopl=0         nv up ei pl zr na po nc

    cs=0008  ss=0010  ds=0023  es=0023  fs=0030  gs=0000             efl=00010246

    8738e300 0000             add     [eax],al                ds:0023:00000001=??

    Resetting default scope

     

    DEFAULT_BUCKET_ID:  DRIVER_FAULT

     

    BUGCHECK_STR:  0x8E

     

    LAST_CONTROL_TRANSFER:  from 8051d6a7 to 8053331e

     

    STACK_TEXT: 

    WARNING: Frame IP not in any known module. Following frames may be wrong.

    b9b3dcec bf801619 b9b3dd64 0012eee4 bf81551f 0x8738e300

    b9b3dd08 bf81553c b9b3dd64 0012eee4 bf81551f win32k!ValidateHwnd+0x5c

    b9b3dd50 804de7ec 0001065e 012eb244 00000000 win32k!NtUserInvalidateRect+0x1d

    b9b3dd50 7c90eb94 0001065e 012eb244 00000000 nt!KiFastCallEntry+0xf8

    0012eecc 77d4b601 0105a943 0001065e 012eb244 ntdll!KiFastSystemCallRet

    0012eed0 0105a943 0001065e 012eb244 00000000 USER32!NtUserInvalidateRect+0xc

    77d4b601 90909090 001134b8 0300ba00 12ff7ffe NikonScan4!GetSource+0x21e93

    ...

     

    From the stack trace, we can tell that NikonScan4.dll made a call into User32, which ultimately ended up calling into win32k.sys down in kernel mode. Win32k was in a function called ValidateHwnd() and then tried to call some function at address 0x8738e300, at which point we tried to dereference an invalid pointer and crashed.

     

    What’s at 0x8738e300?

     

    kd> dc 8738e300

    8738e300  00000000 00000001 00000000 87360350  ............P.6.

    8738e310  00000000 00000001 f71af9fe f71b0030  ............0...

    8738e320  f71afb0e f71afbb4 f71b0098 f71b0214  ................

    8738e330  f71afef6 f71aff8e 07fef800 00000000  ................

    8738e340  f71afffc 00000000 0a0e000a 644c6d4d  ............MmLd

    8738e350  8732ea58 870303e0 ffffffff ffffffff  X.2.............

    8738e360  00000012 00000000 f797f000 f7989905  ................

    8738e370  0000c000 00500050 e1971458 00160016  ....P.P.X.......

     

    kd> !pool 8738e300 2

    Pool page 8738e300 region is Nonpaged pool

    *8738e2f8 size:   50 previous size:    8  (Allocated) *NV 

                  Owning component : Unknown (update pooltag.txt)

     

    Well, that’s bad. 0x8738e300 isn’t actually a valid address of a function. That location contains some user data (specifically, some nonpaged pool).

     

    So, that's why we blew up: the ValidateHwnd() function in win32k made a call to this bad address which contains data instead of code! Let's see if we can figure out why it did this. We can find the return address in win32k!ValidateHwnd on the stack, and unassemble the instructions leading up to the point where we ran off into the weeds.

     

    kd> kv L8

    ChildEBP RetAddr  Args to Child             

    WARNING: Frame IP not in any known module. Following frames may be wrong.

    b9b3dcec bf801619 b9b3dd64 0012eee4 bf81551f 0x8738e300

    b9b3dd08 bf81553c b9b3dd64 0012eee4 bf81551f win32k!ValidateHwnd+0x5c (FPO: [Non-Fpo])

    b9b3dd50 804de7ec 0001065e 012eb244 00000000 win32k!NtUserInvalidateRect+0x1d (FPO: [Non-Fpo])

    b9b3dd50 7c90eb94 0001065e 012eb244 00000000 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9b3dd64)

    0012eecc 77d4b601 0105a943 0001065e 012eb244 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

    0012eed0 0105a943 0001065e 012eb244 00000000 USER32!NtUserInvalidateRect+0xc

    77d4b601 90909090 001134b8 0300ba00 12ff7ffe NikonScan4!GetSource+0x21e93

    77d4b605 001134b8 0300ba00 12ff7ffe 900008c2 0x90909090

     

    The return address from where we made the bad call is bf801619. Let’s unassemble a few instructions backwards from that address (using the handy but often-overlooked “ub” command) and see what the code was doing:

     

    kd> ub bf801619

    win32k!ValidateHwnd+0x2f:

    bf8015ff 8d1c82           lea     ebx,[edx+eax*4]

    bf801602 8bc1             mov     eax,ecx

    bf801604 c1e810           shr     eax,0x10

    bf801607 663b430a         cmp     ax,[ebx+0xa]

    bf80160b 75ad             jnz     win32k!ValidateHwnd+0x3d (bf8015ba)

    bf80160d 807b0801         cmp     byte ptr [ebx+0x8],0x1

    bf801611 7573             jnz     win32k!ValidateHwnd+0xff (bf801686)

    bf801613 ff15e0b298bf call dword ptr [win32k!_imp__PsGetCurrentThread (bf98b2e0)]

     

    OK, so it's pretty simple. Win32k decided which function address to call by reading it from a pointer stored at a hardcoded location (in other words, in a global variable) within Win32k itself. That pointer is located at bf98b2e0. The debugger helpfully tells us that this pointer is intended to contain the address of a function called PsGetCurrentThread, but let’s double-check this and make sure it actually does. At this point, the working assumption would be that this pointer had gotten corrupted somehow.

     

    kd> dd bf98b2e0 L1

    bf98b2e0  804e4a15

     

    Interesting. bf98b2e0 contains the value 804e4a15. This is not even close to the bad address the processor actually called! Remember, from the stack trace, we jumped to 8738e300 instead. What does this pointer actually point to?

     

    kd> ln 804e4a15

    (804e4a15)   nt!PsGetCurrentThread   |  (804e4a51)   nt!KeSetEventBoostPriority

    Exact matches:

        nt!PsGetCurrentThread = <no type information>

     

    Sure enough, 804e4a15 is the address of nt!PsGetCurrentThread.

     

    So, basically, win32k was trying to call PsGetCurrentThread(), and even had the correct pointer in memory to get there, but the processor instead jumped to a bogus address located in the middle of some user data.

     

    At this point it's pretty safe to say that this is a hardware problem, and furthermore, since the relevant memory looks fine, it looks like a problem within the CPU itself. (I’m not an expert on CPU architecture, but if I were to take a wild guess I’d say that maybe the processor had some problem when reading from its L2 cache.)

     

    Upon discovering this, I decided to crack open my case and take a look. It didn’t take long to spot the problem:

    image

    Yes, that's my CPU fan. Notice that the heatsink is completely clogged up with dust!

     

    The resolution to this story: I took a can of compressed air and blew all the dust out of the heatsink. This took care of the problem, and the computer happily scanned hundreds of photos and hasn’t crashed again since. Why was it only crashing when I was scanning photos? Most likely because this was causing the CPU to run at 100% utilization for extended periods of time, and it was simply overheating!

     

  • Ntdebugging Blog

    Windows Internals Beta Exam 71-660

    • 13 Comments

    Correction, Windows Internals Beta Exam 71-660

    This was previously listed incorrectly as 70-660, the actual exam ID is now 71-660

     

    Update 7-18-2008: The link to the exam preparation information has been updated below.

     

    Update 7-21-2008: When registering, there is no need to use a credit card.  Be sure to instead use the following promotional code listed below when registering for the exam: WINT.  If you have already been charged for this exam, please contact Prometric and request a refund, and reference ticket number 3711938.

     

    Hello Windows Debugging Community,  We are super excited to announce a new certification.   With the help of industry partners, including some of our very talented community members,  we have developed a new Windows Internals Certification.   This Certification targets developers and IT professionals that require knowledge of Windows Internals as part of their profession.   Chance are if you are reading this blog post you are part of the target audience.  I encourage you to register and please take the Beta exam.  Please help us to improve the exam by providing feedback during the beta exam.

     

     

    Register for Beta Exam 71-660: TS: Windows® Internals

     

    You are invited to take beta exam 70-660: TS: Windows® Internals. If you pass the beta exam, the exam credit will be added to your transcript and you will not need to take the exam in its released form.

    By participating in beta exams, you have the opportunity to provide the Microsoft Certification program with feedback about exam content, which is integral to development of exams in their released version. We depend on the contributions of experienced IT professionals and developers as we continually improve exam content and maintain the value of Microsoft certifications.

    Please remember that participation in the beta process is completely voluntary and Microsoft makes no promises or guarantees regarding the beta exam process. You can expect to receive your score on the beta exam within 12 weeks of taking the exam, although in some instances, beta exams may take longer to score and your results may be delayed.

    70-660: TS: Windows® Internals counts as credit towards the following certification.

    ·          Microsoft Certified Technology Specialist (MCTS): Windows® Internals  


    Availability

    Registration begins: July 17, 2008

    Beta exam period runs: July 21, 2008August 5, 2008

     

    Receiving this invitation does not guarantee you a seat in the beta; we recommend that you register immediately. Beta exams have limited availability and are operated under a first-come-first-served basis. Once all beta slots are filled, no additional seats will be offered.


    Testing is held at Prometric testing centers worldwide, although this exam may not be available in all countries (see Regional Restrictions).  All testing centers will have the capability to offer this exam in its live version.

     

    Regional Restrictions: India, Pakistan, China


    Registration Information

    You must register at least 24 hours prior to taking the exam.
    Please use the following promotional code when registering for the exam: WINT
    Receiving this invitation does not guarantee you a seat in the beta; we recommend that you register immediately.


    To register in North America, please call:

    Prometric: (800) 755-EXAM (800-755-3926)

     

     

    Outside the U.S./Canada, please contact:

    Prometric: http://www.register.prometric.com/ClientInformation.asp

     

     


    Test Information and Support

    You are invited to take this beta exam at no charge.
    You will be given four hours to complete the beta exam. Please plan accordingly.
    Find exam preparation information: http://blogs.msdn.com/ntdebugging/pages/exam-preparation-information-for-exam-71-660.aspx

     


    Frequently Asked Questions

    For Microsoft Certified Professional (MCP) help and information, you may log in to the MCP Web site at http://www.microsoft.com/learning/mcp/or contact your Regional Service Center: http://www.microsoft.com/learning/support/worldsites.asp.

    What is a beta exam?

    Where can I learn more about the registration process?

    Where can I learn more about the beta exam invitation process?

    Where can I learn more about the new structure of Microsoft Certification?

    Who do I contact for help with this beta exam or other MCP questions?

     

    Thank you.


    Jeff Dailey, Microsoft Global Escalation Services.

  • Ntdebugging Blog

    Windows Hotfixes and Updates - How do they work?

    • 13 Comments

    Today I would like to talk about some of the work the Windows Serviceability (WinSE) team does regarding servicing Windows and releasing updates.

    The operating system is divided into multiple components. Each component can consist of one or more files, registry keys, configuration settings, etc.  WinSE releases updates based on components rather than the entire operating system. This reduces a lot of overhead with having to install updates to components that have not changed. Depending on the severity and applicability of the problem, there are different kinds of release mechanisms. Keep in mind, though, the actual fix still remains the same.

    1.       Updates and Security Updates

    These Updates are typically available on Windows Update. They frequently contain security fixes, and from time to time also contain reliability rollup packages. These updates are thoroughly tested and Microsoft highly recommends that you update your computer with these releases. In fact, most are automatically downloaded to your machine if you have Windows Update turned on. In most cases, Update releases are also available as standalone downloads from the download center.

     

    2.       Hotfixes

    When an individual customer reports a bug to Microsoft for a specific scenario, the WinSE team releases Hotfixes to address these problems. Hotfixes are not meant to be widely distributed and go through a limited amount of testing due to the customer's need for an urgent fix.  Hotfixes are developed in a separate environment than the regular Updates.  This allows Microsoft to release Updates that do not include the Hotfix files, thereby minimizing risk for the customer.

    Once the Hotfix is ready and packaged by WinSE, a KB article is written describing the problem, with instructions on how to obtain the Hotfix.  Microsoft recommends that only customers experiencing the particular problem install the Hotfix for that problem.

    Note: Hotfixes are also sometimes referred to as LDRs, or QFE's (Quick Fix Engineering). The term QFE is an old term that is mostly no longer used in reference to current versions of Windows.

     

    3.       SP  - Service Pack

    The service pack is a major update in the life of an OS. It contains a wide variety of fixes as well as all the GDR and LDR fixes that were released since the previous service pack was shipped. This is a thoroughly tested release and highly recommended by Microsoft for installation. This is usually available as a standalone release, and is then released through Windows Update as well.

     

     

    GDR vs. LDR branches

    Now that we have described the different kinds of updates, let's take a deeper look into how these fixes are built. When a new OS or service pack is released, 2 branches are created from the release code tree -a GDR (general distribution release) branch and a LDR (limited distribution release) branch. Hotfixes are built solely from the LDR branch, while Updates for broad release are built from the GDR branch.

    Service Packs are built from a third branch that contains all Updates , Hotfixes and additional fixes.  This way the new service pack is shipped with all the fixes from both branches.

    Note – Once the new service pack is shipped, the code branches from the previous release are still active and serviced as necessary.

    Installing a Hotfix

    By default, all components on Windows systems start on the GDR branch following each major release. When you install updates from Windows Update for a GDR component, it gets upgraded with the GDR version.

    When you install a specific Hotfix, the files and components in the Hotfix package are migrated to the LDR branch. At this point, that particular component is marked as a LDR component. If you install a newer Update over this component, the Windows servicing technology will automatically install the appropriate latest version from the LDR branch for you. This is possible because each Update package ships with both the GDR and LDR versions of the component.

    Once a component is marked as a LDR component, the only way to move back to the GDR branch is to uninstall all Hotfixes for that component, or move to the next available service pack.

     

    What would happen if a user installed a Hotfix, and then sometime later installed the next service pack? Well, in that case it depends on the Hotfix and when it was built.

    1.       If the Hotfix was built before the service pack, then the component will be moved to the GDR version contained in the service pack.

    2.       If the Hotfix was built after the service pack, the component will be migrated to the post-service pack version of the component, and will stay on the same branch that it was originally on.

     

    In order to make this work, these packages contain both the RTM GDR version, the RTM Hotfix branch, and the SP1 Hotfix and GDR version of each binary.

     

    All fixes built for Windows are cumulative in nature by branch, i.e. a new update will contain the new fix, as well as all the previous fixes for that branch. Referencing the chart above, installing fix #4 can get you fixes #2 and #4 on the GDR branch. If the component is on the LDR branch, then the user would get fixes #1-4.

     

    Finally, the servicing technology has to handle the case where you need the functionality of an older Hotfix (e.g. “Fix #1” in the diagram above) but you may already have installed “Fix #4” which might be a critical security update.  What happens is that when the GDR branch of a fix is installed, it also places a copy of the Hotfix version of the same fix on the system.  When you run the installer for Hotfix #1, it detects that a newer version of the file is already installed, but it also detects that it needs to migrate it to the Hotfix version of the binary that was previously stored on the system. The result is that you end up with the Hotfix binary for Fix #4, which has both the Hotfix you need plus the cumulative set of security fixes.

     

    Stay tuned for more, in the next blog entry, I will talk about the staging mechanism that Windows uses to install Updates and Hotfixes as well as the uninstall process. Also, I will talk about how to determine the branch a file is built from.

     

    - Omer 

     

    More Information

    Description of the standard terminology that is used to describe Microsoft software updates

    Description of the contents of Windows XP Service Pack 2 and Windows Server 2003 software update packages

     

  • Ntdebugging Blog

    Microsoft Windows Dynamic Cache Service

    • 12 Comments

    Excessive cached read I/O is a growing problem.  For over one year we have been working on this problem with several companies.  You can read more about it in the original blog post:

    http://blogs.msdn.com/ntdebugging/archive/2007/11/27/too-much-cache.aspx

    On 32 bit systems, the kernel could address at most 2GB of virtual memory.  This address range is shared and divided up for the many resources that the system needs; one of which is the System File Cache's working set.  On 32 bit systems the theoretical limit is almost 1GB for the cache’s working set; however, when a page is removed from the working set it will end up on the standby page list.  Therefore the system can cache more than the 1 GB limit if there is available memory. The working set; however, is just limited to what can be allocated within the Kernel's 2GB virtual address range.  Since most modern systems have more than 1 GB of physical RAM, the System File Cache's working set's size on a 32 bit system typically isn't a problem.

    With 64 bit systems, the kernel virtual address space is very large and is typically larger than physical RAM on most systems.  On these systems the System File Cache's working set can be very large and is typically about equal to the size of physical RAM.  If applications or file sharing performs a lot of sustained cached read I/O, the System File Cache's working set can grow to take over all of physical RAM.  If this happens, then process working sets are paged out and everyone starts fighting for physical pages and performance suffers.

    The only way to mitigate this problem is to use the provided APIs of GetSystemFileCacheSize() and SetSystemFileCacheSize().  The previous blog post "Too Much Cache" contains sample code and a compiled utility that can be used to manually set the System File Cache's working set size.

    The provided APIs, while offering one mitigation strategy, has a couple of limitations:

    1) There is no conflict resolution between multiple applications.  If you have two applications trying to set the System File Cache's working set size, the last one to call SetSystemFileCacheSize() will win.  There is no centralized control of the System File Cache's working set size.

    2) There is no guidance on what to set the System File Cache's working set size to.  There is no one size fits all solution.  A high cache working set size is good for file servers, but bad for large memory application and a low working set size could hurt everyone's I/O performance.  It is essentially up to 3rd party developers or IT administrators to determine what is best for their server and often times, the limits are determined by a best guesstimate backed by some testing.

    We fully understand that while we provide one way to mitigate this problem, the solution is not ideal. We spent a considerable amount of time reviewing and testing other options.  The problem is that there are so many varied scenarios on how users and applications rely on the System File Cache.  Some strategies worked well for the majority of usage scenarios, but ended up negatively impacting others.  We could not release any code change that would knowingly hurt several applications.

    We also investigated changing some memory manager architecture and algorithms to address these issues with a more elegant solution; however the necessary code changes are too extensive.  We are experimenting with these changes in Windows 7 and there is no way that we could back port them to the current operating systems.  If we did, we would be changing the underlying infrastructure that everyone has been accustomed to.  Such a change would require stress tests of all applications that run on Windows. The test matrix and the chance of regression are far too large.

    So that brings us back to the only provided solution - use the provided APIs.  While this isn't an ideal solution, it does work, but with the limitations mentioned above.  In order to help address these limitations, I've updated the SetCache utility to the Microsoft Windows Dynamic Cache Service.  While this service does not completely address the limitations above, it does provide some additional relief.

    The Microsoft Windows Dynamic Cache Service uses the provided APIs and centralizes the management of the System File Cache's working set size.  With this service, you can define a list of processes that you want to prioritize over the System File Cache by monitoring the working set sizes of your defined processes and back off the System File Cache's working set size accordingly.  It is always running in the background monitoring and dynamically adjusting the System File Cache's working set size.  The service provides you with many options such as adding additional slack space for each process' working set or to back off during a low memory event.

    Please note that this service is experimental and includes sample source code and a compiled binary.  Anyone is free to re-use this code in their own solution.  Please note that you may experience some performance side effects while using this service as it cannot possibly address all usage scenarios. There may be some edge usage scenarios that are negatively impacted.  The service only attempts to improve the situation given the current limitations.  Please report any bugs or observations here to this blog post.  While we may not be able to fix every usage problem, we will try to offer a best effort support.

    Side Effects may include:

    Cache page churn - If the System File Cache's working set is too low and there is sustained cached read I/O, the memory manager may not be able to properly age pages.  When forced to remove some pages in order to make room for new cache pages, the memory manager may inadvertently remove the wrong pages.  This could result in cached page churn and decreased disk performance for all applications.

    Version 1.0.0 - Initial Release

    http://www.microsoft.com/downloads/details.aspx?FamilyID=e24ade0a-5efe-43c8-b9c3-5d0ecb2f39af

    NOTE: The memory management algorithms in Windows 7 and Windows Server 2008 R2 operating systems were updated to address many file caching problems found in previous versions of Windows. There are only certain unique situations when you need to implement the Dynamic Cache service on computers that are running Windows 7 or Windows Server 2008 R2.  For more information on how to determine if you are experiencing this issue and how to resolve it, please see the More Information section of Microsoft Knowledge Base article 976618 - You experience performance issues in applications and services when the system file cache consumes most of the physical RAM.

  • Ntdebugging Blog

    NTDebugging Puzzler 0x00000004: This didn’t puzzle the Debug Ninja, how about you?

    • 12 Comments

    Hello NTDebuggers, we have been very impressed with the responses we’ve gotten to our previous puzzlers so far.  We invited the Debug Ninja to come up with a real challenge for this week.

    This server blue screened with a Bug Check 0xD1: DRIVER_IRQL_NOT_LESS_OR_EQUAL.  The challenge this week is to tell us, as specifically as possible, why it crashed.  We’ll give you a hint, the complete answer is not that ebx+5441F815h points to an invalid address.

    1: kd> .bugcheck

    Bugcheck code 000000D1

    Arguments e074281d 00000002 00000001 ba502493

     

    1: kd> kv

    ChildEBP RetAddr  Args to Child

    f78b6544 ba502493 badb0d00 00000001 00000000 nt!_KiTrap0E+0x2a7 (FPO: [0,0] TrapFrame @ f78b6544)

    f78b65e0 ba50d9d8 00000020 8c32cab8 00000022 tcpip!GetAddrType+0x19f (FPO: [Non-Fpo]) (CONV: stdcall)

    f78b6694 ba50dc56 8c32cab8 8ca71c2c 000005c8 tcpip!IPRcvPacket+0x66c (FPO: [Non-Fpo]) (CONV: stdcall)

    f78b66d4 ba50dd58 00000000 8ca63440 8ca71c0a tcpip!ARPRcvIndicationNew+0x149 (FPO: [Non-Fpo]) (CONV: stdcall)

    f78b6710 bada5550 8c4b53b8 00000000 f78b678c tcpip!ARPRcvPacket+0x68 (FPO: [Non-Fpo]) (CONV: stdcall)

    f78b6764 ba9c614b 8cac2ad0 f78b6784 00000002 NDIS!ethFilterDprIndicateReceivePacket+0x1d2 (FPO: [Non-Fpo]) (CONV: stdcall)

     

    1: kd> .trap f78b6544

    ErrCode = 00000002

    eax=8c32cab8 ebx=8c323008 ecx=00000001 edx=00000001 esi=8ca71c18 edi=f78b6618

    eip=ba502493 esp=f78b65b8 ebp=f78b65e0 iopl=0         nv up ei pl zr na pe nc

    cs=0008  ss=0010  ds=0023  es=0023  fs=0030  gs=0000             efl=00250246

    tcpip!GetAddrType+0x19f:

    ba502493 008b15f84154    add     byte ptr [ebx+5441F815h],cl ds:0023:e074281d=??

     

    The remainder of this puzzler is quite long, click here to see the complete debug notes required to solve this puzzlerPost your responses to this page (and not the complete debug page), so we can keep all the comments together.  Also, we won’t post any of your responses until Friday.


    [Update, posted 4/30/2008]

    Today is Wednesday and so far we haven’t received any complete responses; the partial answers we have received are close but no one has determined the root cause of the problem.  When looking at problems like this it is often useful to ask “why?” when you think you have the answer and think about what other information may be available.  In this situation it is possible to identify a specific problem and even determine appropriate action to fix the problem.

    Perhaps we were a bit overzealous in posting 14 pages of assembly as a puzzler.  Below is an abbreviated debug with less assembly, the link to the complete debug is still available for those of you who want to try the full challenge.  Also, we are going to break our promise not to post responses until Friday and we have posted some responses that we have gotten so far, neither of these responses completely identifies the problem but they are getting close.

     

    1: kd> dd @ebx+5441F815

    e074281d  ???????? ???????? ???????? ????????

    e074282d  ???????? ???????? ???????? ????????

    e074283d  ???????? ???????? ???????? ????????

    e074284d  ???????? ???????? ???????? ????????

    e074285d  ???????? ???????? ???????? ????????

    e074286d  ???????? ???????? ???????? ????????

    e074287d  ???????? ???????? ???????? ????????

    e074288d  ???????? ???????? ???????? ????????

    1: kd> !pte e074281d

                   VA e074281d

    PDE at 00000000C0603818    PTE at 00000000C0703A10

    contains 000000021B980963  contains E154FC1000000400

    pfn 21b980 -G-DA--KWEV                           not valid

                           Proto: 00000000E154FC10

     

    1: kd> ub ba50d9d8

    tcpip!IPRcvPacket+0x658:

    ba50d9c4 51              push    ecx

    ba50d9c5 50              push    eax

    ba50d9c6 53              push    ebx

    ba50d9c7 ff75f4          push    dword ptr [ebp-0Ch]

    ba50d9ca ff75f8          push    dword ptr [ebp-8]

    ba50d9cd ff75ec          push    dword ptr [ebp-14h]

    ba50d9d0 ff7508          push    dword ptr [ebp+8]

    ba50d9d3 e84a040000      call    tcpip!DeliverToUser (ba50de22)

     

    1: kd> uf tcpip!DeliverToUser

    tcpip!DeliverToUser:

    tcpip!DeliverToUser+0xc1:

    ba50ded9 8b45f0          mov     eax,dword ptr [ebp-10h]

    ba50dedc 29451c          sub     dword ptr [ebp+1Ch],eax

    ba50dedf 8b471c          mov     eax,dword ptr [edi+1Ch]

    ba50dee2 ff7508          push    dword ptr [ebp+8]

    ba50dee5 2b4510          sub     eax,dword ptr [ebp+10h]

    ba50dee8 57              push    edi

    ba50dee9 8945fc          mov     dword ptr [ebp-4],eax

    ba50deec e817ffffff      call    tcpip!UpdateIPSecRcvBuf (ba50de08)

     

    tcpip!DeliverToUser+0xd9:

    ba50def1 807e0906        cmp     byte ptr [esi+9],6

    ba50def5 753e            jne     tcpip!DeliverToUser+0x12f (ba50df35)

     

    tcpip!DeliverToUser+0xdf:

    ba50def7 8b430c          mov     eax,dword ptr [ebx+0Ch]

    ba50defa 83b88c00000007  cmp     dword ptr [eax+8Ch],7

    ba50df01 0f857a510000    jne     tcpip!DeliverToUser+0x124 (ba513081)

     

    tcpip!DeliverToUser+0xeb:

    ba50df07 837f1000        cmp     dword ptr [edi+10h],0

    ba50df0b 741a            je      tcpip!DeliverToUser+0x114 (ba50df27)

     

    tcpip!DeliverToUser+0xf1:

    ba50df0d 640fb61551000000 movzx   edx,byte ptr fs:[51h]

    ba50df15 8b8880010000    mov     ecx,dword ptr [eax+180h]

    ba50df1b 3bca            cmp     ecx,edx

    ba50df1d 0f857145ffff    jne     tcpip!DeliverToUser+0x103 (ba502494)

     

    tcpip!DeliverToUser+0x103:

    ba502494 8b15f84154ba    mov     edx,dword ptr [tcpip!_imp__KeNumberProcessors (ba5441f8)]

    ba50249a 0fbe12          movsx   edx,byte ptr [edx]

    ba50249d 3bca            cmp     ecx,edx

    ba50249f 0f8582ba0000    jne     tcpip!DeliverToUser+0x114 (ba50df27)

     

    tcpip!DeliverToUser+0x110:

    ba50df23 c645f402        mov     byte ptr [ebp-0Ch],2

     

    tcpip!DeliverToUser+0x114:

    ba50df27 640fb60d51000000 movzx   ecx,byte ptr fs:[51h]

    ba50df2f 898880010000    mov     dword ptr [eax+180h],ecx

     

    tcpip!DeliverToUser+0x114:

    ba5024a5 e979ba0000      jmp     tcpip!DeliverToUser+0x110 (ba50df23)

     


     

    [Update: our answer, posted 5/2/2008]

    In response:  I would like to congratulate the people who figured this out and say thank you to all of the people who gave this a try and sent in a response.  I’m not sure if we made a challenge that was too easy, too difficult, or too long, but we did not get as many responses as we had expected.  If you looked at this and chose not to post a comment, or you have looked at our previous puzzlers but chose to skip this one, let us know why so we can post better puzzlers in the future.

    Here is the answer…

    Experienced assembly readers will recognize that this instruction is a valid instruction, but it takes action that no assembly writer would ever take.  An offset of 5441F815 is too big to be realistic; no structure is 5441F815 bytes long.

    1: kd> .trap f78b6544

    ErrCode = 00000002

    eax=8c32cab8 ebx=8c323008 ecx=00000001 edx=00000001 esi=8ca71c18 edi=f78b6618

    eip=ba502493 esp=f78b65b8 ebp=f78b65e0 iopl=0         nv up ei pl zr na pe nc

    cs=0008  ss=0010  ds=0023  es=0023  fs=0030  gs=0000             efl=00250246

    tcpip!GetAddrType+0x19f:

    ba502493 008b15f84154    add     byte ptr [ebx+5441F815h],cl ds:0023:e074281d=??

     

    Why is this instruction telling us to go to a crazy offset?  One possible cause is that the instruction is corrupt; a good debug method for this problem would be to unassemble the code around this instruction to see if the adjacent instructions look valid, and then to compare these instructions to ones in a known good version of tcpip.sys.  Because this instruction was not corrupt neither of these steps helped, so I started looking at how we got to this instruction.

    Looking at the prior function on the stack, IPRcvPacket, I see that we actually called DeliverToUser and not GetAddrType.  Why is our current instruction in GetAddrType instead of DeliverToUser?  It is possible that the call went to the wrong place, that DeliverToUser called something else which returned to the wrong place, or that somehow the flow of execution did not go as intended.

    1: kd> ub ba50d9d8

    tcpip!IPRcvPacket+0x658:

    ba50d9c4 51              push    ecx

    ba50d9c5 50              push    eax

    ba50d9c6 53              push    ebx

    ba50d9c7 ff75f4          push    dword ptr [ebp-0Ch]

    ba50d9ca ff75f8          push    dword ptr [ebp-8]

    ba50d9cd ff75ec          push    dword ptr [ebp-14h]

    ba50d9d0 ff7508          push    dword ptr [ebp+8]

    ba50d9d3 e84a040000      call    tcpip!DeliverToUser (ba50de22)

     

    The next step I took was to analyze the DeliverToUser assembly to see how we might have ended up in GetAddrType instead of DeliverToUser.  What I found, and what several of our readers found, was that DeliverToUser contained a jump that went to 1 byte away from where we encountered the bogus instruction.

    ba50df1d 0f857145ffff    jne     tcpip!DeliverToUser+0x103 (ba502494)

     

    Why would eip point to ba50d9d3 instead of ba50d9d4?  That is the challenging question in this exercise, because the answer is not obvious.  Some engineers will conclude that the hardware must not have done what we asked it to do, and say that the hardware must be at fault.  However, we don’t really have any proof at this time that the hardware has actually done something wrong.  Hardware problems usually manifest themselves as a bit flip, where one bit is changed from the correct value.  We have gone from a 4 (0100) to a 3 (0011); a 3 bit change is hard to blame on hardware.

    To answer the question “Why would eip point to ba50d9d3 instead of ba50d9d4?” we need to carefully analyze the instruction at ba50df1d.  I broke out my trusty instruction set reference and looked up the inner workings of the jne instruction.  On page 3-542 of the Intel® 64 and IA-32 Architectures Software Developer's Manual Volume 2A: Instruction Set Reference, A-M I found the layout for a jne to a 32 bit offset.  The first two bytes are 0F 85, and the next 8 bytes are the offset we are going to jump too.  This is our opcode:

    0f 85 ff ff 45 71

    Remember that by the time we make this jump the instruction pointer will have been moved to the next instruction, that will be at ba50df23 (ba50df1d plus the 6 bytes that are in this instruction).  If we take this offset (ff ff 45 71) and add it to the next instruction we see that we’ll end up at ba502494 as expected.

    1: kd> ?ba50df23+ffff4571

    Evaluate expression: -1169152876 = ba502494

     

    If we change just one bit in this opcode, if we change 71 (0111 0001) to be 70 (0111 0000), we end up at ba502493 instead.  Now we can conclude that the hardware must have made a mistake, and now that we know what bit was flipped we can confidently say that we have identified the mistake that was made.

    1: kd> ?ba50df23+ffff4570

    Evaluate expression: -1169152877 = ba502493

     

    We still have some unanswered questions.  The most common question I get when I’ve found a bit flip is what piece of hardware is broken?  Unfortunately I can’t answer this question with the data I have.  In this case the jne instruction was good when we read it to put it in the dump but obviously it was bad when it was executed.  Thinking about the parts needed to get the instruction from RAM and execute it I could speculate that a processor, riser board, or motherboard could be at fault but I don’t have any data that proves where the problem happened.  It is unlikely that hardware diagnostics will find this type of failure because it is intermittent.  Unless the problem manifests itself while the diagnostics are running, they will likely report that there is no problem.  In the case of this server I wasn’t able to find out specifically what failed, uptime was more important than troubleshooting so a whole new server was put in place of this one and the problem has not been seen since.

    Bit flips can be caused by any number of problems.  Problems with a processor, a processor riser board, a motherboard, or RAM are common causes.  As we have documented before in this blog improper voltage or overheating can also cause these types of problems.  However the potential list of bit-flip causes is nearly endless; power supplies, power cables, incoming power fluctuations, radiation from nearby electronics, even sun spots, can all cause bit flips.

    I should also explain why the stack showed that we were in GetAddrType instead of DeliverToUser.  This is because tcpip.sys has been optimized with Basic Block Tools (BBT) optimization, blocks of code from the same function are located in different pages to reduce the cache hits in common code paths.  This means that blocks of the GetAddrType code are located next to the DeliverToUser code.  As demonstrated below there is a block of GetAddrType code that ends with an unconditional jmp at ba50248f and there is a block of DeliverToUser code that starts at ba502494.

    1: kd> ub ba502494

    tcpip!GetAddrType+0x9e:

    ba502474 f6401401        test    byte ptr [eax+14h],1

    ba502478 0f84bd760000    je      tcpip!GetAddrType+0xb4 (ba509b3b)

    ba50247e 85db            test    ebx,ebx

    ba502480 0f84bd6b0200    je      tcpip!GetAddrType+0xa8 (ba529043)

    ba502486 32c0            xor     al,al

    ba502488 e967770000      jmp     tcpip!GetAddrType+0x15a (ba509bf4)

    ba50248d 33c9            xor     ecx,ecx

    ba50248f e993770000      jmp     tcpip!GetAddrType+0x19b (ba509c27)

    1: kd> u

    tcpip!DeliverToUser+0x103:

    ba502494 8b15f84154ba    mov     edx,dword ptr [tcpip!_imp__KeNumberProcessors (ba5441f8)]

    ba50249a 0fbe12          movsx   edx,byte ptr [edx]

    ba50249d 3bca            cmp     ecx,edx

    ba50249f 0f8582ba0000    jne     tcpip!DeliverToUser+0x114 (ba50df27)

    ba5024a5 e979ba0000      jmp     tcpip!DeliverToUser+0x110 (ba50df23)

    ba5024aa 90              nop

    ba5024ab 90              nop

    ba5024ac 90              nop

     

    Congratulations to those who have read this far.  Hopefully you now understand the cause of a problem that has stumped many engineers, and you have some new tools in your toolbox when you’re investigating a tricky problem.  Remember to keep asking “why?” and not to assume anything; those are the approaches I used to find the source of this problem.





  • Ntdebugging Blog

    The Memory Shell Game

    • 12 Comments

    Hello, this is Somak.  Today I’d like to drop some Memory Manager info on the blog that I’ve used to communicate in brief (believe it or not) how the system deals with memory.  If you are ever faced with checking how much Available Memory you have(or don’t have), poor system performance, questions about page faults, or having a Working Set Trimming performance issue, or just want a primer into how Windows manages memory on the system, be not afraid and read on!

    How this memory stuff works

    The fastest and most expensive memory is built into the CPU.  The next fastest and less expensive is physical RAM.  Next we have the hard drive, followed by remote storage or backup.  Each step down the ladder adds significantly to access time.  For example, physical RAM can be almost one million times faster than a hard disk.  Since it is volatile and cost considerably more than hard disk space, we are limited at how much we can put in the system.  This limit is far less than the much slower and non-volatile hard disk.  Due to these design constraints we have a tiered memory structure in the computer.  To achieve the fastest response times and best overall performance, an operating system must efficiently use this tiered memory structure.  It must do its best to reduce the need to retrieve data from a slower storage media like the hard disk.  It has to do this while juggling the memory and I/O demand from all running processes.  The following paragraphs are an overview of how the Memory Manager achieves this in Windows.  A more detailed description can be found in Chapter 7 of Microsoft Windows Internals, Fourth Edition (ISBN: 0-7356-1917-4).  This book is the great source for how stuff works in Windows.

    First let’s lay out some definitions.  They will be useful later on when I talk about the interactions.  These definitions are high level to maintain brevity.

    Virtual Memory – This is a memory that an operating system can address.  Regardless of the amount of physical RAM or hard drive space, this number is limited by your processor architecture.  On a 32 bit processor you are limited to 4 GB of addressable virtual memory (2^32).  With a default installation on a 32 bit box (not using /3GB) the kernel reserves 2GB for itself.  Applications are left with 2GB of addressable virtual memory.  When applications execute they are only presented with this 2GB of addressable memory.  Each application gets its own 2GB virtual memory to play with.  If you have 50 processes running, you’ll have 50 independent 2GB Virtual Memory address spaces and one 2GB Virtual Address space for kernel.  This is possible because Virtual Memory always exists, but doesn't really exist (hence the term virtual).  We basically lie to the application and say, here is 2GB of memory address space for you to use.  This memory isn’t allocated until the application explicitly uses it.  Once the application uses the page, it becomes committed.  A virtual memory page is then translated to a physical memory page.  From this translation, the virtual page can reside in physical RAM or on the hard disk.

    Physical Memory –  This is the physical storage media.  It can be physical RAM, the hard disk, optical disks, tape backups, etc.  This is anything that can store data.  Most times when people talk about Physical Memory, they refer to physical RAM (the memory sticks on your motherboard), but with virtual page translation, physical memory can also be on the hard drive (in your paging file).  Physical RAM is limited by your processor architecture.

    Committed Memory –  When an application touches a virtual memory page (reads/write/programmatically commits) the page becomes a committed page.  It is now backed by a physical memory page.  This will usually be a physical RAM page, but could eventually be a page in the page file on the hard disk, or it could be a page in a memory mapped file on the hard disk.  The memory manager handles the translations from the virtual memory page to the physical page.   A virtual page could be in located in physical RAM, while the page next to it could be on the hard drive in the page file.

    Commit Limit –  This is the maximum amount of memory that all your applications and the OS can commit.  If you had 50 applications fully allocate their 2 GB of virtual address space, you would need 100GB of commit limit (ignore kernel memory usage to keep the numbers simple).  So 100GB of committed pages can be backed by physical RAM or the hard drive.  If you have 100 GB of RAM, you could handle this memory load.   In most cases, 100 GB of RAM isn't economically feasible so the Commit Limit is comprised of physical RAM and the page file.  If you have 2 GB of physical RAM and 98 GB of page file, then your commit limit would be 100 GB.

    Page file –   This is the storage area for virtual memory that has been committed.  It is located on the hard drive.  Since hard drive space is cheaper than physical RAM, it is an inexpensive way to increase the commit limit.

    Working Set – This is a set of virtual memory pages (that are committed) for a process and are located in physical RAM.  These pages fully belong to the process.  A working set is like a "currently/recently working on these pages" list.

    Modified pages - Once a virtual memory page leaves the process's working set, it is moved to another list.  If the page has been modified, it is placed on the modified page list.  This page is in physical RAM.  A thread will then write the page to the page file and move it to the standby list.

    Standby pages - This is a page that has left the process' working set.  This page is in physical RAM.  A standby page is like a cache for virtual memory pages.  It is still associated with the process, but not in its working set.  If the process touches the page, it is quickly faulted back into the working set.  That page also has one foot out the door.  If another process or cache needs more memory, the process association is broken and it is moved to the free page list.  Most of the pages in available memory are actually standby pages.  This makes sense when you realize that these pages can be quickly given to another process (hence available), but you should also understand that they are page caches for working sets and can be quickly given back if the process touches the page again.  The vast majority of available memory is not wasted or empty memory.

    Free pages - When a page is taken off of the standby page list, it is moved to the Free page list.  This page is in physical RAM.  These pages are not associated with any process.   When a process exits, all of its pages are then dumped onto this list. Typically, there is a very small to no amount of free pages hanging around physical RAM. 

    Zeroed pages - When a free page is zeroed out, it is placed on the Zero page list.  This page is in physical RAM.  These are the pages that are given to processes that are making memory allocations.  Due to C2 security requirements, all pages must be scrubbed before handed to a new process.  When the system is idle, a thread will scrub free pages and put them on this list.  Only a small amount of zero pages are required to handle the typical small memory allocations of processes.  Once this list is depleted, and if there is demand for more pages, we pull pages off of the Free page list and scrub them on the fly.  If the Free page list is depleted, then we pull pages off of the standby list, scrub them on the fly and hand them to the new process.

    What is Task Manager telling me?

    Prior to Windows Vista, Task Manager reports memory usage using accounting methods that you probably are not expecting.  It is because of these accounting practices, that we rarely use Task Manager to gauge system performance and memory usage.  We typically use it for a quick overview or to kill processes.  I highly recommend using Performance Monitor (perfmon.msc) for investigating performance issues.  Here's the breakdown of the numbers on the Performance tab:

    Physical Memory

    Total - The is the total physical RAM installed in the system.

    Available - This is the total of the Standby, Free and Zeroed list.  Free and Zeroed makes sense, but Standby seems odd at first.  Standby pages were added to this number because they are available for a quick scrub and given to a new process.  So they are technically available (with minimal effort).

    System Cache- This is the total of the Standby list and the size of the system working set (which includes the file cache).  Standby pages are added to this list because they are cached pages for working sets.

    PF Usage - This is the total number of committed pages on the system.  It does not tell you how many are actually written to the page file.  It only tells you how much of the page file would be used if all committed pages had to be written out to the page file at the same time.

    Commit Charge

    Total - This is the total virtual memory that has been committed.  This includes all committed memory for all processes and the kernel.

    Limit - This is the maximum amount of committed memory this system can handle.  This is a combination of physical RAM and the page file.

    Peak – This is the highest amount of memory committed thus far on this system, since boot.

    How does this work?

    The memory manager optimizes physical RAM usage across the entire system.  Since physical RAM is a finite resource, it has to balance sharing this critical resource amongst all process, the kernel and file I/O.   It tries to keep disk I/O to a minimum, which results in a more responsive system.  It does this by moving pages around to meet the demand of the system.

    Typically, large sections of physical RAM are used for file cache.  This is cache is necessary to improve disk performance.  Without it, disk I/O would make the system crawl along at an nearly unusable pace.  The file system cache is just like a working set for a process.  Pages removed from the file cache are moved to the standby or modified page list.  Many of the standby pages in RAM are probably file cache pages that were removed from its working set.  For example, on a file server, if you see 8 GB of available memory, most of these pages are probably standby pages for the file cache.  The file cache's working set could be 500 MB, but the 8 GB of standby pages should also be considered part of the file cache.

    Now let's take a look at how the memory manager handles processes.  While an application is working with its virtual memory pages, the memory manager keeps the pages in the process' working set.  Since the vast majority of application do not use all of its memory all the time, some pages will age.  Old pages are removed from the working set.  If they are modified, they are moved to the modified list.  The page is saved to the page file and moved to the standby list.  If the page hasn't been modified, it is moved directly to the standby list.  These pages will remain on the standby page list until there is a demand for it.

    If the application touches the page again, it is soft faulted back into the process' working set.  If the process doesn't use the page for a very long time, or if the demand for the page is greater elsewhere, the page is moved off of the standby list.  It is disassociated with the process and moved to a the free page list.  From the free page list, the page is scrub on demand or lazily and placed on the zero page list.  It is from the zero page list that other processes or the kernel or the file cache will get a new page.

    If after a very long time the application once again needs a page that is not in its working set, the memory manager will handle the memory fault.  If the page is on the standby list, it is quickly put back into the process' working set.  If the page is no longer in the standby list, a hard fault occurs.  The memory manager issues I/O to the hard disk to read the page(s) from the page file.  Once the I/O complete, the page is placed back into the process' work set.

    All of this is done to keep physical RAM highly utilized and disk I/O to a minimum.  We don't want to allow process to horde physical RAM for pages that are rarely used.  The physical RAM must be shared with other processes, the kernel and the file cache.  If you see lots of available memory on your system, rest assured that it is not going to waste.  The vast majority is on standby lists for processes and the file cache.

    Also note that page file usage isn't that bad.  The page file allows the Memory Manager to save modified pages before placing the page on the standby list.  The page is still in physical RAM and can be quickly faulted back into the process.  This method gives the process a chance to reclaim an old page and it allows the page to be quickly used if there is demand elsewhere.

    The best way to see the totals of these lists is to use a kernel debugger (live or postmortem).  Use the !memusage command and you'll get an output like this:

    0: kd> !memusage

    loading PFN database

    loading (100% complete)

    Compiling memory usage data (99% Complete).

    Zeroed:    414 (  1656 kb)

                   Free:      2 (     8 kb)

    Standby: 864091 (3456364 kb)

    Modified:    560 (  2240 kb)

        ModifiedNoWrite:     30 (   120 kb)

    Active/Valid: 182954 (731816 kb)

             Transition:      2 (     8 kb)

                    Bad:      0 (     0 kb)

                Unknown:      0 (     0 kb)

    TOTAL: 1048053 (4192212 kb)

    Of the 4GB of physical RAM, only 1.6 MB are on Zeroed or free pages.  731 MB is in process, system and file cache working sets.  2 MB are on the modified page list.  The vast majority, 3.4 GB, is on the standby list.  On this server, most people will see 3.4 GB of wasted physical RAM, but you will know better.

    What should I be worried about?

    Typically you shouldn't be worried about these things, until you have a performance problem.  If your system is sluggish or slow to respond or you are getting errors about out of memory, then you need to rely on this information.  You will need to collect a performance monitor log of the problem time.  If the counter list is daunting, then use the Performance Monitor Wizard to configure the performance monitor log.

    Once the log is collected, you'll need to analyze several counters.  I'm not going into detail about how to review performance monitor logs this time.  I'll save that lengthy topic for another time.  For now I'll focus on the counters relevant to the Memory Manager.

    One of the biggest reasons for slow performance and sluggish system responsiveness is disk bottleneck.  Look at Physical Disk\% Idle Time, Avg. Disk sec/Read and Avg. Disk sec/Write counters.  If your system drive is under 50% idle or your disk response times are way above your drive specifications, then you need to investigate further.  Look at the Memory\Available Mbytes.  You should have a couple hundred Mbytes of Available Memory.  This is one of the most important performance monitor counters.  If this number drops too low, your standby lists, process working sets and cache will be greatly reduced.  You'll need to find out if a process is consuming physical RAM.  Check for large process working sets or for large file cache.

    You will also need to see if paging is really affecting system performance.  Take a look at Memory\Pages Input/sec and correlate that to Physical Disk\Avg. Disk sec/Read.  Pages Input/sec is the number of pages being read in from the page file.  These are the hard faults (when the page wasn't on the standby list).  If your Avg. Disk sec/Read is close to your drive's specification and the drive's idle time is high, than paging really isn't a problem.  Small amounts of hard faults are expected as applications will every once in a while re-touch an old page.  As long as this I/O is not consistent or the disk can't keep up, you probably will not notice this impact.

    You can also look at Memory\Pages Output/sec and Physical Disk\Avg. Disk sec/Write.  These are the page commits to the page file when a modified page is removed from a process' working set.  As long as the disk can keep up with the writes, this shouldn't be a problem.  Remember that once the page is saved to the page file, it is placed on the standby list.  If there isn't a great demand for new pages, it can remain on the standby list for a very long time.  When the process touches the old virtual page again, it can be soft faulted back into the working set.  If there is great demand for memory, you'll see process working sets aggressively being trimmed.  Unless there is memory pressure, this is all done with lazy I/O, so you should not see much of an impact from this activity.

    The Memory Manager works to meet current demand and prepares for future demand when possible.  You need to look at a performance monitor log to see if there is memory pressure on the system.  You'll see this in low Available Mbytes and reductions in process working sets.  You'll be able to correlate this to increase disk I/O to the page file.  If you have established that there is memory pressure on the box, you need to figure where that demand is coming from.  Check for working set increases from processes, file cache or bottlenecked disk I/O to data drives.

  • Ntdebugging Blog

    Windows Performance Toolkit - Xperf

    • 11 Comments

    I recently came across a very interesting profiling tool that is available in Vista SP1 and Server 08 called the Windows Performance Analyzer. You can use this tool to profile and diagnose different kinds of symptoms that the machine is experiencing. This tool is built on top off the Event Tracing for Windows (ETW) infrastructure. It uses the ETW providers to record kernel events and then display them in a graphical format.

    Performance Analyzer provides many different graphical views of trace data including:

    1. CPU Sampling
    2. CPU and Disk utilization by process and thread
    3. Interrupt service routine and deferred procedure call
    4. Hard faults
    5. Disk I/O Detail

    What you will need

    Download the latest version of the Windows Performance Tools Kit, and install it on your machine. (http://www.microsoft.com/whdc/system/sysperf/perftools.mspx : Windows Performance Tools Kit, v.4.1.1 (QFE)) You will need to find the toolkit that corresponds to your processor architecture. Currently there are 3 versions available i.e. X86, IA64, X64.

    After installation you should be able to see 2 new tools. The first one is Xperf, which is a command line tool that is used to capture the trace. The second is called XperfView, which graphically interprets the trace that has been collected by Xperf.

    You will need to run the Xperf and XperfView from an elevated command prompt for all functionality.

    Starting a Trace

    For many tasks all you need for effective analysis is a kernel trace.  For this example, we'll use the –on DiagEasy parameter to enable several kernel events including: image loading; disk I/O; process and thread events; hard faults; deferred procedure calls; interrupts; context switches; and, and performance counters.  From an elevated command prompt launch xperf –on DiagEasy.

    This starts the kernel logger in sequential mode to the default file "\kernel.etl"; uses a default buffer size of 64K, with a minimum of 64 and a maximum of 320 buffers. 

    Stopping a Trace

    To stop a trace, type xperf –d <filename>.etl at the command line. This will stop the trace and output the file.

    Viewing a Trace

    There are 2 ways to view the trace. From an Elevated Command prompt, launch xperf <filename>.etl, or
    launch the XperfView tool and open the file manually. When you open the trace file, you should see something similar like this.

    NOTE - While you need to run xperf from an elevated command prompt in order to record a trace you do not need an elevated command prompt in order to *analyze* a trace.  

    Using the Chart Selector tab, you can select all the graphs that you want to look at. To drill down in each chart, you can select the Summary table. For instance, in the CPU Sampling chart, the summary table gets you the summary of the processes that were running, with information like the amount of CPU time, CPU %, stacks (if the stacks were collected in the trace, see below). When looking at the Summary table for the Disk I/O chart, you can see which processes were writing files (the filename too!) to disk, as well as how much time it took.

    You also have the ability to zoom in on a selected area. Another really cool feature is the ability to overlay multiple graphs on one frame. This way you can correlate different pieces of data together very easily.

    Also, you select which counter instances you want to see in each specific chart. On the top right corner of each chart is a drop down box from where you can select the counter instances. For instance on the Disk I/O chart, you can select Disk 0, Disk 1, or a combination as well.

    You can also view detailed information about the system that the trace was taken on. Click on the Trace menu item, and select System Configuration.

    Xperf Kernel Flags and Groups

    In the first sample Xperf command we ran, xperf –on DiagEasy. I am sure many of you were wondering what DiagEasy means. DiagEasy is a group of kernel events that are predefined by the Windows Performance Toolkit. This group includes Process, Threads, Kernel and User Image Load/Unload, Disk I/O, DPCs and Context Switch events.

    When we used the xperf –on DiagEasy command, we did not specify an individual provider, so we enabled the kernel events for all the ETW providers on the system. If you want to enable events for a specific provider, you can the following format xperf -on: (GUID|KnownProviderName)[:Flags[:Level]]. For more information about ETW providers, Kernel Flags and Groups, you can run the xperf –help providers command.

    Stack Tracing

    One of the most powerful features in Performance Analyzer is the ability to visualize stacks. It's important to note that this requires no special instrumentation in the code – only that you have symbols for the binary components you are interested in analyzing.

    When the trace is setup to collect the stacks, Performance Analyzer will display call stack summary information for the events that had stack walking enabled. Here is an example that takes a trace (with stack tracing enabled) of the entire system while running a "find string" utility.. We can use the Stack Tracing feature of Xperf to record a stack when certain events happen, or take sample at regular intervals over time. See xperf –help stackwalk output for more info.

    Below, we will use the Stack Tracking feature of Xperf to take stack samples at regular intervals. With this output, we will be able to determine where the CPU is spending most of its time within a process.

    xperf -on latency -stackwalk Profile

    Latency is the kernel group to enable certain events, including the profile event which records the CPUs' activity every millisecond. The "-stackwalk Profile" flag tells Xperf to record stack walks on every profile event, which makes the profile information much more useful. In other words, in order to get profile information with stack walks you need to turn on the profile event, and turn on stack walking for that event.

    Note that decoding of stacks requires that symbol decoding be configured. However stacks can be recorded without symbols, and can even be viewed without symbols, although they are much less useful without symbols. I only mention this in the event you're trying to record a trace of a problematic machine with little time to mess around with _NT_SYMBOL_PATH.

    To get a trace with the stack information, do the following:

    1. Run the command, xperf -on latency -stackwalk Profile.
    2. Run the application that you wish to analyze, then
    3. You can end the trace by using the regular xperf –d <filename>.etl command.
    4. Load the trace in the viewer and then select the Load Symbols from the Trace drop down menu.
    5. Once the symbols are loaded, select an interesting region on the CPU sampling graph.
    6. Right click and select Summary Table.

    Click on the selector tab to bring up the column chooser list. Then select "Process name", "Process", "Stack", "Weight" and "%Weight". These are the most useful columns when looking at stacks from the sample profile event. You should get a view similar to this.

     

    At this point I need to mention a few of the restrictions with stack walking coupled with when and how it works.

    ·                Xperf stack walking is not available on XP

    ·                On Vista stack walking is available for x86, and is available for x64 as of Vista SP1.

    ·                On Windows 7 stack walking is available.

    ·                Stack walking on x64 is complicated. You have to set DisablePagingExecutive in the registry, as documented here:

    http://social.msdn.microsoft.com/Forums/en-US/wptk_v4/thread/282e5beb-0afd-411b-9a81-a0bbbf569dfe/

    REG ADD "HKLM\System\CurrentControlSet\Control\Session Manager\Memory Management" -v DisablePagingExecutive -d 0x1 -t REG_DWORD –f

    Sample Case

    I recently came across a case where the customer was complaining that DPC processing was taking up too much CPU time. We ran Xperf on the machine and drilled down into the DPC activity on the machine.

    From the Xperf graph, I was able to confirm that the customer was actually seeing high DPC usage. I selected the Summary for this chart, and got the list of drivers that were actually taking up CPU time.

    Right off the bat, I could identify the driver that had a lot of DPC activity. I also noted that the average duration for each DPC from that driver was taking 788 microseconds. This is way too high. Each DPC should be taking a maximum of 100 microseconds.

     

    - Omer

      

    Reference

    Performance.Analyzer.QuickStart.xps – This is shipped with the performance toolkit.

    From an elevated command prompt, launch xperf -help

    http://www.microsoft.com/whdc/system/sysperf/perftools.mspx

    http://blogs.gotdotnet.com/pigscanfly/archive/2008/02/16/using-xperf-to-take-a-trace.aspx

    http://www.microsoft.com/whdc/Driver/tips/DPC_ISR.mspx

  • Ntdebugging Blog

    Detecting and automatically dumping hung GUI based windows applications..

    • 11 Comments

    Written by Jeff Dailey 

    My name is Jeff,  I’m an Escalation Engineer on CPR Platforms team.  Following Tate’s blog on scoping hangs I’d like discus a common category of hangs and some creative ways to track them down.  I will be providing a couple of labs to go with this post that you can run and debug on your machine and I will also be showing you how to write a hang detection tool that will dump processes that go unresponsive.  In addition to this I will be writing several more blog entries about the various hang scenarios contained in the badwindows.zip that is included with this blog.

    GUI Hangs

    Sometimes a Windows application that is GUI (Graphical User Interface) based, that is to say uses windows, buttons, scroll bars etc. may stop responding (Not Responding status in Task Manager).  When this happens in most cases the rest of the operating system seems to continue functioning ok.  However the application does not repaint or respond to mouse clicks or key strokes.  Sometimes these types of problem may be transient.   Your app may hang once or twice a day for 10-30 seconds.  In other cases it may hang for long periods of time or never recover.

    To get a better understand of this scenario it’s important to understand that all GUI based Windows applications work by passing messages to one another via a message queues.   Each Windows application typically has a single main thread that is responsible for processes these messages.   Though the application may be multi threaded there will typically be one thread processes messages.  This functionally is normally implement in WinMain.    This thread does different tasks based on the messages it receives.   It could open a dialog, create anther thread, or take actions based on a mouse click of even send a message to another Windows application or applications.

    When your application stops responding it’s generally due to this thread making a blocking / synchronous call that takes too long.  If the thread is unable to pull incoming messages from the OS it will appear to be hung.   Most of the time once you have the dump of the process you can look at thread 0 by doing a ~0s in cdb or windbg.  Then do a KB and see what the thread is blocking on or possibly looping in that is preventing it from processing messages.  If thread 0 is not the thread processing your messages you may be able to find it by dumping all the thread stacks, ~*kb

    The problem is you may not be able to fire up cdb or windbg to get a dump in time.  Or you may have a non technical user community that does not know about debuggers or creating dumps.  In this case you can do what I sometimes do. 

    Create your own tool.

    That’s right.  Sometimes I will see a scenario that warrants a slightly more elegant solution and there is nothing more powerful than a determined engineer and a C complier.   

    What is required?  Visual Studio (The Express edition is free), Windows SDK (free), the debugger SDK (free with Debugging Tools Install), and a little knowledge of how Windows works.

    Let’s take a moment and think about what our ideal debug application will and won’t do.  

    1.     It will be easy to use and configure and use.

    2.     It will not break or negatively impact our operating system.  That is to say, it will not use much CPU or resources.

    3.     It will wait quietly for our desired condition (in this case a hung window) to manifest.

    4.     It will spring into action and gather the critical information about the state of our misbehaving application by creating a dump file without raising a fuss.

    5.     It will be multi user aware and not place dumps in insecure locations, this means the dumps will go in the user’s temp directory.

    6.     We will only collect a limited number of dump files so we do not fill up the hard drive.

    7.     It will notify the admin of a hang and dump event by putting a message in the event log. 

    8.     It will execute an optional binary when a hang is detected.

     

    Here are the details of how it will work.

    To keep things simple we will just create a console application.  The application will be called dumphungwindow.exe.  We will run in a loop until we collect the desired number of dump files.  We will wake up every so many seconds,  get the top most window, loop through each window sending it a message with the SendMessageTimeout  API and if any window takes more then what we signify as our timeout we will create a dump of that process and log an event in the event log.   

    I have the sample dumphungwindow.zip and badwindow.zip embedded within it available for download here, it has the EXEs and the visual studio 2005 project with all of the source.  The tool project is called dumphungwindow, and the test application is in a project called badwindow.  This project contains a lab with three different hang scenarios that cause a window to stop responding. 

    The command line options are as follows.

    C:\source\dumphungwindow\debug>dumphungwindow.exe /?
     This sample application shows you how to use the debugger
     help api to dump an application if it stop responding.

     This tool depends on dbghelp.dll, this comes with the Microsoft debugger tools on www.microsoft.com

     Please make sure you have the debugger tools installed before running this tool.
     This tool is based on sample source code and is provided as is without warranty.

     feel free to contact jeffda@microsoft.com to provide feedback on this sample application

     /m[Number] Default is 5 dumps

     The max number of dumps to take of hung windows before exiting.

     /t[Seconds]  Default is 5 seconds

     The number of seconds a window must hang before dumping it.

     /p[Seconds] Default is 0 seconds

     The number of seconds to pause when dumping before continuing scan.

     /s[Seconds] Default is 5 seconds.

     The scan interval in seconds to wait before rescanning all windows.

     /d[DUMP_FILE_PATH] The default is the SystemRoot folder

     The path or location to place the dump files.

     /e[EXECUTABLE NAME] This allows you to start another program if an application hangs

    To run the tool simply start dumphungwindow.exe  The output should look something like this.

    C:\source\dumphungwindow\debug>dumphungwindow.exe
    Dumps will be saved in C:\Users\jeff\AppData\Local\Temp\
    scanning for hung windows

    ****

    To start our bad application extract the badwindowapp.zip file contained in the dumphungwindows.zip

     

    Then run badwindow.exe and from the menu select hang \ hang type 2.

     

    After a few seconds findhungwindow should detect the unresponsive badwindow.exe and generate a dump.

     

    Hung Window found dumping process (7064) badwindow.exe

    Dumping unresponsive process

    C:\Users\jeffda\AppData\Local\Temp\HWNDDump_Day5_29_2007_Time10_36_38_Pid7064_badwindow.exe.dmp

     

     

    Please take a moment and review the source.  I’ve added comments that explain how we go about finding the hung window, and how we go about dumping it to a dump file you can open in windbg..

     

    Feel free to download and try out dumphungwindow against the badwindow.exe application.  Try looking at “hang type 1” first as that will be my next blog.  Over the coming weeks I’ll be writing about hang types 1,2 and 3 in the badwindow.exe application.   Once you have the dump file you can open it by inside of windbg via file \ open crash dump.  See Debugging tools for the install location.

     

    I hope you find this tool and sample helpful.

     

    Thank you Jeff-

     

     

    /********************************************************************************************************************

    Warranty Disclaimer

    --------------------------

    This sample code, utilities, and documentation are provided as is, without warranty of any kind. Microsoft further disclaims all

    implied warranties including without limitation any implied warranties of merchantability or of fitness for a particular  purpose.

    The entire risk arising out of the use or performance of the product and documentation remains with you.

     

    In no event shall Microsoft be liable for any damages whatsoever  (including, without limitation, damages for loss of business

    profits, business interruption, loss of business information, or other pecuniary loss) arising out of the use of or inability to

    use the sample code, utilities, or documentation, even if  Microsoft has been advised of the possibility of such damages.

    Because some states do not allow the exclusion or limitation of liability for consequential or incidental damages, the above

    limitation may not apply to you.

     

    ********************************************************************************************************************/

     

    #include <stdio.h>

    #include <windows.h>

    #include <dbghelp.h>

    #include <psapi.h>

     

    // don't warn about old school strcpy etc.

    #pragma warning( disable : 4996 )

     

    int iMaxDump=5;

    int iDumpsTaken=0;

    int iHangTime=5000;

    int iDumpPause=1;

    int iScanRate=5000;

    HANDLE hEventLog;

    char * szDumpLocation;

    int FindHungWindows(void);

    char * szDumpFileName = 0;

    char * szEventInfo = 0;

    char * szDumpFinalTarget = 0;

    char * szModName = 0;

    char * szAppname = 0;

    DWORD dwExecOnHang = 0;

     

    #define MAXDUMPFILENAME 1000

    #define MAXEVENTINFO 5000

    #define MAXDUMPFINALTARGET 2000

    #define MAXDUMPLOCATION 1000

    #define MAXAPPPATH 1000

    #define MAXMODFILENAME 500

    #define HMODSIZE 255

     

    int main(int argc, char * argv[])

    {

          int i;

          int z;

          size_t j;

          char scan;

     

          // check to make sure we have dbghelp.dll on the machine.

          if(!LoadLibrary("dbghelp.dll"))

          {

                printf("dbghelp.dll not found please install the debugger tools and place this tool in \r\nthe debugging tools directory or a copy of dbghelp.dll in this tools directory\r\n");

                return 0;

          }

     

          // Allocate a buffer for our dump location

          szDumpLocation = (char *)malloc(MAXDUMPLOCATION);

          {

                if(!szDumpLocation)

                {

                printf("Failed to alloc buffer for szdumplocation %d",GetLastError());

                return 0;

                }

          }

     

          szAppname = (char *)malloc(MAXAPPPATH);

          {

                if(!szAppname)

                {

                printf("Failed to alloc buffer for szAppname  %d",GetLastError());

                return 0;

                }

          }

     

          // We use temp path because if we are running under terminal server sessions we want the dump to go to each

          // users secure location, ie. there private temp dir. 

          GetTempPath(MAXDUMPLOCATION, szDumpLocation );

         

          for (z=0;z<argc;z++)

          {

                switch(argv[z][1])

                {

                case '?':

                      {

                      printf("\n This sample application shows you how to use the debugger \r\n help api to dump an application if it stop responding.\r\n\r\n");

                      printf("\n This tool depends on dbghelp.dll, this comes with the Microsoft debugger tools on www.microsoft.com");

                      printf("\n Please make sure you have the debugger tools installed before running this tool.");

                      printf("\n This tool is based on sample source code and is provided as is without warranty.");

                      printf("\n feel free to contact jeffda@microsoft.com to provide feedback on this sample application\r\n\r\n");

                      printf(" /m[Number] Default is 5 dumps\r\n The max number of dumps to take of hung windows before exiting.\r\n\r\n");

                      printf(" /t[Seconds]  Default is 5 seconds\r\n The number of seconds a window must hang before dumping it. \r\n\r\n");

                      printf(" /p[Seconds] Default is 0 seconds\r\n The number of seconds to pause when dumping before continuing scan. \r\n\r\n");

                      printf(" /s[Seconds] Default is 5 seconds.\r\n The scan interval in seconds to wait before rescanning all windows.\r\n\r\n");

                      printf(" /d[DUMP_FILE_PATH] The default is the SystemRoot folder\r\n The path or location to place the dump files.  \r\n\r\n");

                      printf(" /e[EXECUTABLE NAME] This allows you to start another program if an application hangs\r\n\r\n");

     

                      return 0;

                      }

                case 'm':

                case 'M':

                      {

                            iMaxDump = atoi(&argv[z][2]);

                            break;

                      }

                case 't':

                case 'T':

                      {

                            iHangTime= atoi(&argv[z][2]);

                            iHangTime*=1000;

                            break;

                      }

                case 'p':

                case 'P':

                      {

                            iDumpPause= atoi(&argv[z][2]);

                            iDumpPause*=1000;

                            break;           

                      }

                case 's':

                case 'S':

                      {

                            iScanRate = atoi(&argv[z][2]);

                            iScanRate*=1000;             

                            break;

                      }

                case 'd':

                case 'D':

                      { // Dump file directory path

                            strcpy(szDumpLocation,&argv[z][2]);

                            j = strlen(szDumpLocation);

     

                            if (szDumpLocation[j-1]!='\\')

                            {

                                  szDumpLocation[j]='\\';

                                  szDumpLocation[j+1]=NULL;

                            }

                            break;

                      }

                case 'e':

                case 'E':

                      { // applicaiton path to exec if hang happens

                            strcpy(szAppname,&argv[z][2]);

                            dwExecOnHang = 1;

                            break;

                      }

                }

          }

     

     

          printf("Dumps will be saved in %s\r\n",szDumpLocation);

          puts("scanning for hung windows\n");

     

          hEventLog = OpenEventLog(NULL, "HungWindowDump");

     

          i=0;

          scan='*';

          while(1)

          {

                if(i>20)

                {

                      if ('*'==scan)

                      {

                      scan='.';

                }

                      else

                      {

                      scan='*';

                }

                      printf("\r");

                i=0;

                }

                i++;

                putchar(scan);

                if(!FindHungWindows())

                {

                      return 0;

                }

                if (iMaxDump == iDumpsTaken)

                {

                      printf("\r\n%d Dumps taken, exiting\r\n",iDumpsTaken);

                      return 0;

                }

                Sleep(iScanRate);

          }

     

          free(szDumpLocation);

          return 0;

    }

     

    int FindHungWindows(void)

    {

    DWORD dwResult = 0;

    DWORD ProcessId = 0;

    DWORD tid = 0;

    DWORD dwEventInfoSize = 0;

     

    // Handles

    HWND hwnd = 0;

    HANDLE hDumpFile = 0;

    HANDLE hProcess = 0;

    HRESULT hdDump = 0;

     

    SYSTEMTIME SystemTime;

    MINIDUMP_TYPE dumptype = (MINIDUMP_TYPE) (MiniDumpWithFullMemory | MiniDumpWithHandleData | MiniDumpWithUnloadedModules | MiniDumpWithProcessThreadData);

     

    // These buffers are presistant.

     

    // security stuff to report the SID of the dumper to the event log.

    PTOKEN_USER pInstTokenUser;

    HANDLE ProcessToken;

    TOKEN_INFORMATION_CLASS TokenInformationClass = TokenUser;

    DWORD ReturnLength =0;

     

    // This allows us to get the first window in the chain of top windows.

    hwnd = GetTopWindow(NULL);

    if(!hwnd)

    {

          printf("Could not GetTopWindow\r\n");

          return 0;

    }

     

    // We will iterate through all windows until we get to the end of the list.

    while(hwnd)

    {

          // Get the process ID for the current window   

          tid = GetWindowThreadProcessId(hwnd, &ProcessId);

     

          // Sent a message to this window with our timeout. 

          // If it times out we consider the window hung

          if (!SendMessageTimeout(hwnd, WM_NULL, 0, 0, SMTO_BLOCK, iHangTime, &dwResult))

          {

                // SentMessageTimeout can fail for other reasons, 

                // if it's not a timeout we exit try again later

                if(ERROR_TIMEOUT != GetLastError())

                {

                      printf("SendMessageTimeout has failed with error %d\r\n",GetLastError());

                      return 1;

                }

                      // Iint our static buffers points.

                      // On our first trip through if we have not

                      // malloced memory for our buffers do so now.

                      if(!szModName)

                      {

                            szModName = (char *)malloc(MAXMODFILENAME);

                            {

                                  if(!szModName)

                                  {

                                  printf("Failed to alloc buffer for szModName %d",GetLastError());

                                  return 0;

                                  }

                            }

                      }

                      if(!szDumpFileName)// first time through malloc a buffer.

                      {

                            szDumpFileName = (char *)malloc(MAXDUMPFINALTARGET);

                            {

                                  if(!szDumpFileName)

                                  {

                                        printf("Failed to alloc buffer for dumpfilename %d",GetLastError());

                                        return 0;

                                  }

                            }

                      }

                      if(!szDumpFinalTarget)// first time through malloc a buffer.

                      {

                            szDumpFinalTarget= (char *)malloc(MAXDUMPFINALTARGET);

                            {

                                  if(!szDumpFinalTarget)

                                  {

                                  printf("Failed to alloc buffer for dumpfiledirectory %d",GetLastError());

                                  return 0;

                                  }

                            }

                      }

                      if(!szEventInfo)

                      {

                            szEventInfo= (char *)malloc(MAXEVENTINFO);

                            {

                                  if(!szEventInfo)

                                  {

                                  printf("Failed to alloc buffer for szEventInfo %d",GetLastError());

                                  return 0;

                                  }

                            }

                      }

                      // End of initial buffer allocations.

     

                GetLocalTime (&SystemTime);

               

                // Using the process id we open the process for various tasks.

                hProcess = OpenProcess(PROCESS_ALL_ACCESS,NULL,ProcessId);

                if(!hProcess )

                {

                      printf("Open process of hung window failed with error %d\r\n",GetLastError());

                      return 1;

                }

                // What is the name of the executable?

                GetModuleBaseName( hProcess, NULL, szModName,MAXMODFILENAME);

     

                printf("\r\n\r\nHung Window found dumping process (%d) %s\n",ProcessId,szModName);

     

                // Here we build the dump file name time, date, pid and binary name

                sprintf(szDumpFileName,"HWNDDump_Day%d_%d_%d_Time%d_%d_%d_Pid%d_%s.dmp",SystemTime.wMonth,SystemTime.wDay,SystemTime.wYear,SystemTime.wHour,SystemTime.wMinute,SystemTime.wSecond,ProcessId,szModName);

                strcpy(szDumpFinalTarget,szDumpLocation);

                strcat(szDumpFinalTarget,szDumpFileName);

     

                // We have to create the file and then pass it's handle to the dump api

                hDumpFile = CreateFile(szDumpFinalTarget,FILE_ALL_ACCESS,0,NULL,CREATE_ALWAYS,FILE_ATTRIBUTE_NORMAL,NULL);

                if(!hDumpFile)

                {

                      printf("CreateFile failed to open dump file at location %s, with error %d\r\n",szDumpLocation,GetLastError());

                      return 0;

                }

     

                printf("Dumping unresponsive process\r\n%s",szDumpFinalTarget);

               

                // This dump api will halt the target process while it writes it's

                // image to disk in the form a dump file.

                // this can be opened later by windbg or cdb for debugging.

                if(!MiniDumpWriteDump(hProcess,ProcessId,hDumpFile,dumptype ,NULL,NULL,NULL))

                {

                      // We do this on failure

                      hdDump = HRESULT_FROM_WIN32(GetLastError());

                      printf("MiniDumpWriteDump failed with a hresult of %d last error %d\r\n",hdDump,GetLastError());

                      CloseHandle (hDumpFile);

                      return 0;

                }

                else

                {

                      // If we are here the dump worked.  Now we need to notify the machine admin by putting a event in

                      // the application event log so someone knows a dump was taken and where it is stored.

                      sprintf(szEventInfo,"An application hang was caught by findhungwind.exe, the process was dumped to %s",szDumpFinalTarget);

     

                      // We need to get the process token so we can get the user sit so ReportEvent will have the

                      // User name / account in the event log.

                      if (OpenProcessToken(hProcess,      TOKEN_QUERY,&ProcessToken ) )

                      {

                            // Make the firt call to findout how big the sid needs to be.    

                            GetTokenInformation(ProcessToken,TokenInformationClass, NULL,NULL,&ReturnLength);

                            pInstTokenUser = (PTOKEN_USER) malloc(ReturnLength);

                            if(!pInstTokenUser)

                            {

                                  printf("Failed to malloc buffer for InstTokenUser exiting error %d\r\n",GetLastError());

                                  return 0;

                            }

                            if(!GetTokenInformation(ProcessToken,TokenInformationClass, (VOID *)pInstTokenUser,ReturnLength,&ReturnLength))

                            {

                                  printf("GetTokenInformation failed with error %d\r\n",GetLastError());

                                  return 0;

                            }

                      }

                      // write the application event log message. 

                      // This will show up as source DumpHungWindow

                      dwEventInfoSize=(DWORD)strlen(szEventInfo);

         

                      ReportEvent(hEventLog,EVENTLOG_WARNING_TYPE,1,1,pInstTokenUser->User.Sid,NULL,dwEventInfoSize,NULL,szEventInfo);

     

                      // Free to token buffer, we don't want to leak anything.

                      free(pInstTokenUser);

                     

                      // In additon to leaking a handle if you don't close the handle

                      // you may not get the dump to flush to the hard drive.

                      CloseHandle (hDumpFile);

                      printf("\r\nDump complete");

                     

                      // This allows you to execute something if you get a hang like crash.exe

                      if (dwExecOnHang)

                      {

                            system(szAppname);

                      }

                     

                      //  The Sleep is here so in the event you want to wait N seconds

                      //  before collecting another dump

                      //  you can pause.  This is helpful if you want to see if any

                      //  forward progress is happening over time

                     

                      Sleep(iDumpPause);

                }

                // Once we are at our threadshold for max dumps

                // we exit so we do not fill up the hard drive.

                iDumpsTaken++;

                if (iMaxDump == iDumpsTaken)

                {

                      return 0;

                }

            }

            // This is where we traverse to the next window.

                hwnd = GetNextWindow(hwnd, GW_HWNDNEXT);

          }

          return 1;

    }

     

  • Ntdebugging Blog

    How Windows Starts Up (part 1 of 4)

    • 11 Comments

    Hi folks, my name is David and I’m an Escalation Engineer for Microsoft.  Since Bryan wrote about How Windows Shuts Down, I thought it would be a good idea to cover How Windows Starts Up.

     

    This information applies specifically to Windows 2000, Windows XP, and Windows Server 2003.  I will blog separately on the boot changes in Windows Vista.

     

    Additional information about this topic may be found in Chapter 5 of Microsoft Windows Internals by Russinovich and Solomon and also on TechNet:  http://technet.microsoft.com/en-us/library/bb457123.aspx

     

    Methodology

    The key to understanding and troubleshooting system startup issues is to accurately ascertain the point of failure.  To facilitate this determination, I have divided the boot process into the following four phases.

     

                    1. Initial

                    2. Boot Loader

                    3. Kernel

                    4. Logon

     

    Over the next few weeks, I’ll be describing each of these phases in detail and providing appropriate guidance for troubleshooting relevant issues for each phase. 

     

    Initial Phase

    The Initial Phase of boot is divided into the Power-On Self Test (POST) and Initial Disk Access. 

     

    Power-On Self Test

    POST activities are fully implemented by the computer’s BIOS and vary by manufacturer.  Please refer to the technical documentation provided with your hardware for details.  However, regardless of manufacturer, certain generic actions are performed to ensure stable voltage, check RAM, enable interrupts for system usage, initialize the video adapter, scan for peripheral cards and perform a memory test if necessary.  Depending on manufacturer and configuration, a single beep usually indicates a successful POST. 

     

    Troubleshooting the POST

    ü  Make sure you have the latest BIOS and firmware updates for the hardware installed in the system.

    ü  Replace the CMOS battery if it has failed.

    ü  Investigate recently added hardware (RAM, Video cards, SCSI adapters, etc.)

    ü  Remove recently added RAM modules.

    ü  Remove all adapter cards, then replace individually, ensuring they are properly seated.

    ü  Move adapter cards to other slots on the motherboard.

    ü  If the computer still will not complete POST, contact your manufacturer.

     

    Initial Disk Access

    Depending on the boot device order specified in your computer’s BIOS, your computer may attempt to boot from a CD-ROM, Network card, Floppy disk, USB device or a hard disk.  For the purposes of this document, we’ll assume that we’re booting to a hard disk since that is the most common scenario.

     

    Before we discuss the sequence of events that occur during this phase of startup, we need to understand a little bit about the layout of the boot disk.  The structure of the hard disk can be visualized this way:  (Obviously, these data areas are not to scale)

     

     

     

    Hard disks are divided into Cylinders, Heads and Sectors.  A sector is the smallest physical storage unit on a disk and is almost always 512 bytes in size.  For more information about the physical structure of a hard disk, please refer to the following Resource Kit chapter:  http://www.microsoft.com/resources/documentation/windowsnt/4/server/reskit/en-us/resguide/diskover.mspx

     

    There are two disk sectors critical to starting the computer that we’ll be discussing in detail:  

     

    ·         Master Boot Record (MBR)

    ·         Boot Sector

     

    The MBR is always located at Sector 1 of Cylinder 0, Head 0 of each physical disk.   The Boot Sector resides at Sector 1 of each partition.  These sectors contain both executable code and the data required to run the code.

     

    Please note that there is some ambiguity involved in sector numbering.  Cylinder/Head/Sector (CHS) notation begins numbering at C0/H0/S1.  However, Absolute Sector numbering begins numbering at zero.  Absolute Sector numbering is often used in disk editing utilities such as DskProbe.  These differences are discussed in the following knowledge base article:

    Q97819  Ambiguous References to Sector One and Sector Zero

    http://support.microsoft.com/default.aspx?scid=kb;EN-US;Q97819

     

    Now that we have that straight, when does this information get written to disk?  The MBR is created when the disk is partitioned.  The Boot Sector is created when you format a volume.  The MBR contains a small amount of executable code called the Master Boot Code, the Disk Signature and the partition table for the disk.  At the end of the MBR is a 2-byte structure called a Signature Word or End of Sector marker, which should always be set to 0x55AA.  A Signature Word also marks the end of an Extended Boot Record (EBR) and the Boot Sector.

     

    The Disk Signature, a unique number at offset 0x1B8, identifies the disk to the operating system.  Windows 2000 and higher operating systems use the disk signature as an index to store and retrieve information about the disk in the registry subkey HKLM\System\MountedDevices.

     

    The Partition Table is a 64-byte data structure within the MBR used to identify the type and location of partitions on a hard disk.  Each partition table entry is 16 bytes long (four entries max).  Each entry starts at a predetermined offset from the beginning of the sector as follows:

     

                                    Partition 1                           0x1BE    (446)

                                    Partition 2                           0x1CE    (462)

                                    Partition 3                           0x1DE    (478)

                                    Partition 4                           0x1EE    (494)

     

    The following is a partial example of a sample MBR showing three partition table entries in-use and one empty:

     

    000001B0:                                             80 01

    000001C0: 01 00 07 FE BF 09 3F 00 - 00 00 4B F5 7F 00 00 00

    000001D0: 81 0A 07 FE FF FF 8A F5 – 7F 00 3D 26 9C 00 00 00

    000001E0: C1 FF 05 FE FF FF C7 1B – 1C 01 D6 96 92 00 00 00

    000001F0: 00 00 00 00 00 00 00 00 – 00 00 00 00 00 00

     

    Let’s take a look at each of the fields of a partition table entry individually.  For each of these explanations, I’ll use the first partition table entry above and highlight the relevant section.  Keep in mind that these values are little-endian.

     

    Byte Offset

    Field Length

    Sample Value

    Field Description

    0x1BE

    8 Bits

    0x80

    Boot Indicator

                    00=Do Not Use for Booting

                    80=Active partition (Use for Booting)

    000001B0:                                             80 01

    000001C0: 01 00 07 FE BF 09 3F 00 - 00 00 4B F5 7F 00     

     

    0x1BF

    8 Bits

    0x01

    Starting Head

    000001B0:                                             80 01

    000001C0: 01 00 07 FE BF 09 3F 00 - 00 00 4B F5 7F 00

     

    0x1C0

    0x1C1

    2 Byte

    Word

    0x01

    Starting Sector

    Only the first 6 bits are used.  The upper 2 bits of this byte are used by the Starting Cylinder field.

    0x00

    Starting Cylinder

    Uses 1 byte + 2 bits from the Starting Sector field to make up the cylinder value.  The Starting Cylinder is a 10-bit number with a maximum value of 1023.

    000001B0:                                             80 01

    000001C0: 01 00 07 FE BF 09 3F 00 - 00 00 4B F5 7F 00

     

     

     

    0x1C2

    8 Bits

    0x07

    System ID

    Defines the volume type.  0x07=NTFS

    000001B0:                                             80 01

    000001C0: 01 00 07 FE BF 09 3F 00 - 00 00 4B F5 7F 00

     

    Other Possible System ID Values:  

    Partition Type

    ID Value

    0x01

    FAT12 primary partition or logical drive (fewer than 32,680 sectors in the volume)

    0x04

    FAT16 partition or logical drive (32,680–65,535 sectors or 16 MB–33 MB)

    0x05

    Extended partition

    0x06

    BIGDOS FAT16 partition or logical drive (33 MB–4 GB)

    0x07

    Installable File System (NTFS partition or logical drive)

    0x0B

    FAT32 partition or logical drive

    0x0C

    FAT32 partition or logical drive using BIOS INT 13h extensions

    0x0E

    BIGDOS FAT16 partition or logical drive using BIOS INT 13h extensions

    0x0F

    Extended partition using BIOS INT 13h extensions

    0x12

    EISA partition

    0x42

    Dynamic disk volume

    0x86

    Legacy FT FAT16 disk *

    0x87

    Legacy FT NTFS disk *

    0x8B

    Legacy FT volume formatted with FAT32 *

    0x8C

    Legacy FT volume using BIOS INT 13h extensions formatted with FAT32 *

     

    Partition types denoted with an asterisk (*) indicate that they are also used to designate non-FT configurations such as striped and spanned volumes.

     

    0x1C3

    8 Bits

    0xFE

    Ending Head      (0xFE=254 decimal)

    000001B0:                                             80 01

    000001C0: 01 00 07 FE BF 09 3F 00 - 00 00 4B F5 7F 00

     

    0x1C4

    0x1C5

    2 Byte

    Word

    0xBF

    Ending Sector

    As with the Starting Sector, it only uses the first 6 bits of the byte.  The upper 2 bits are used by the Ending Cylinder field.

    0x09

    Ending Cylinder

    Uses 1 byte in addition to the upper 2 bits from the Ending Sector field to make up the cylinder value.  The Ending Cylinder is a 10-bit number with a maximum value of 1023.

    000001B0:                                             80 01

    000001C0: 01 00 07 FE BF 09 3F 00 - 00 00 4B F5 7F 00

     

    0x1C6

    32 Bits

    0x3F000000

    Relative Sectors

    The offset from the beginning of the disk to the beginning of the volume, counting by sectors.

    0x0000003F = 63

    000001B0:                                             80 01

    000001C0: 01 00 07 FE BF 09 3F 00 - 00 00 4B F5 7F 00

     

     

    0x1CA

    32 Bits

    0X4BF57F00

    Total Sectors

    The total number of sectors in the volume.

    0x007FF54B = 8,385,867 Sectors = 4GB

    000001B0:                                             80 01

    000001C0: 01 00 07 FE BF 09 3F 00 - 00 00 4B F5 7F 00

     

    Are you with me so far?  Good!  Now, Cylinder/Sector encoding can be a bit tricky, so let’s take a closer look. 

     

    Cylinder - Sector Encoding

    16

    15

    14

    13

    12

    11

    10

    9

    8

    7

    6

    5

    4

    3

    2

    1

    Cylinder bits 1-8

    Cyl bits

    9 & 10

    Sector value

    Bits 1-6

     

    As you can see, the Sector value occupies the lower 6 bits of the word and the Cylinder occupies the upper 10 bits of the word.  In our example, the starting values for Cylinder and Sector are 01 00.  Values in the MBR use reverse-byte ordering, which is also referred to as ‘little-endian’ notation.  Therefore, we swap the bytes and find that our starting values are Cyl 0, Sec 1.

     

    Our ending values are more interesting:  BF 09.  First, we swap the bytes and obtain a hex value of 0x09BF.  This value in binary notation is 100110111111.  The following table illustrates how we derive the correct partition table values from these bytes:

     

    Example:  BF 09

    8

    7

    6

    5

    4

    3

    2

    1

    10

    9

    6

    5

    4

    3

    2

    1

    0

    0

    0

    0

    1

    0

    0

    1

    1

    0

    1

    1

    1

    1

    1

    1

    10 Cylinder value bits 1-8

    Cyl bits

    9 & 10

    Sector value

    bits 1-6

     

    The 6 low bits are all set to 1, therefore our Sector value is 111111 or 63.   You can see above how the bits are arranged for the Cylinder value.  The value above is 1000001001 (521).  Since both Cylinder and Head values begin numbering at zero, we have a total of 522 Cylinders and 255 Heads represented here.  This gives us an ending CHS value of:  522 x 255 x 63 = 8,385,930 sectors. 

     

    Subtracting the starting CHS address (Cylinder 0, Head 1, Sector 1) (63) gives us the total size of this partition:  8,385,867 sectors or 4GB.  We can verify this number by comparing it to the Total Sectors represented in the partition table:  4B F5 7F 00.  Applying reverse-byte ordering gives us 00 7F F5 4B which equals 8,385,867 sectors.

     

    So, now that we have an understanding of what is contained within the structures on the disk, let’s look at the sequence of events that occur.  Remember, this is just after POST has successfully completed.

     

    1.       The motherboard ROM BIOS attempts to access the first boot device specified in the BIOS.  (This is typically user configurable and can be edited using the BIOS configuration utility.)

     

    2.       The ROM BIOS reads Cylinder 0, Head 0, and Sector 1 of the first boot device.

     

    3.       The ROM BIOS loads that sector into memory and tests it.

    a.       For a floppy drive, the first sector is a FAT Boot Sector.

    b.      For a hard drive, the first sector is the Master Boot Record (MBR).

     

    4.       When booting to the hard drive, the ROM BIOS looks at the last two signature bytes of Sector 1 and verifies they are equal to 55AA.

    a.       If the signature bytes do not equal 55AA the system assumes that the MBR is corrupt or the hard drive has never been partitioned.  This invokes BIOS Interrupt 18, which displays an error that is BIOS-vendor specific such as “Operating System not found”.

    b.      If the BIOS finds that the last two bytes are 55AA, the MBR program executes.

     

    5.       The MBR searches the partition table for a boot indicator byte 0x80 indicating an active partition.

    a.       If no active partition is found, BIOS Interrupt 18 is invoked and a BIOS error is displayed such as “Operating System not found”.

    b.      If any boot indicator in the MBR has a value other than 0x80 or 0x00, or if more than one boot indicator indicates an active partition (0x80), the system stops and displays “Invalid partition table”.

    c.       If an active partition is found, that partition’s Boot Sector is loaded and tested.

     

    6.       The MBR loads the active partition’s Boot Sector and tests it for 55AA.

    a.       If the Boot Sector cannot be read after five retries, the system halts and displays “Error loading operating system”.

    b.      If the Boot Sector can be read but is missing its 55AA marker, “Missing operating system” is displayed and the system halts.

    c.       The bootstrap area is made up of a total of 16 sectors (0-15).  If sector 0 for the bootstrap code is valid, but there is corruption in sectors 1-15, you may get a black screen with no error.  In this case, it may be possible to transplant sectors 1-15 (not Sector 0) from another NTFS partition using DskProbe.

    d.      If the Boot Sector is loaded and it passes the 55AA test, the MBR passes control over to the active partition’s Boot Sector.

     

    7.       The active partition’s Boot Sector begins executing and looks for NTLDR.  The contents of the Boot Sector are entirely dependent on the format of the partition.   For example, if the boot partition is a FAT partition, Windows writes code to the Boot Sector that understands the FAT file system.  However, if the partition is NTFS, Windows writes NTFS-capable code.  The role of the Boot Sector code is to give Windows just enough information about the structure and format of a logical drive to enable it to read the NTLDR file from the root directory.   The errors at this point of the boot process are file system specific.  The following are possible errors with FAT and NTFS Boot Sectors.

    a.       FAT:  In all cases it displays “press any key to restart” after either of the following errors.

    (1)    If NTLDR is not found “NTLDR is missing” is displayed

    (2)    If NTLDR is on a bad sector, “Disk Error” displays.

    b.      NTFS:  In all cases it displays “Press CTRL+ALT+DEL to restart” after any of the following errors.

    (1)    If NTLDR is on a bad sector, “A disk read error occurred” is displayed.  This message may also be displayed on Windows 2000 or higher systems if Extended Int13 calls are required, but have been disabled in the CMOS or SCSI BIOS.  This behavior may also be seen if an FRS (File Record Segment) cannot be loaded or if any NTFS Metadata information is corrupt.

    (2)    If NTLDR is not found, “NTLDR is missing” displays.

    (3)    If NTLDR is compressed, “NTLDR is compressed” displays.

     

    8.       Once NTLDR is found, it is loaded into memory and executed.  At this point the Boot Loader phase begins.

     

    Troubleshooting the Initial Phase (Initial Disk Access)

    If you are unable to boot Windows and the failure is occurring very early in the boot process, begin by creating a Windows boot floppy and using it to attempt to boot the system.

     

                    Q119467 How to Create a Bootable Disk for an NTFS or FAT Partition

                    http://support.microsoft.com/default.aspx?scid=kb;EN-US;Q119467

     

    If you are unable to boot to Windows NT with a floppy, skip to the section titled “Unable to boot using floppy”.

     

    If you can successfully start the computer from the boot disk, the problem is limited to the Master Boot Record, the Boot Sector, or one or more of the following files:  NTLDR, NTDetect.com, or Boot.ini.  After Windows is running, you should immediately back up all data before you attempt to fix the Boot Sector or Master Boot Record.

     

    1.       Run a current virus scanning program to verify that no virus is present.

    2.       Select the method of troubleshooting based upon the error generated.

    ·         Operating System not found

    Typical BIOS-specific error indicating no 55AA signature on the MBR.  This must be repaired manually using a disk editor such as DskProbe.

    Warning:  Running FixMBR or FDISK /MBR in this case will clear the partition table.

    ·         Invalid Partition Table

    May be repaired using DiskProbe – check for multiple 0x80 boot indicators.

    ·         Error Loading Operating System

    This error indicates an invalid Boot Sector.  Use the “Repairing the Boot Sector” section below.

    ·         Missing Operating System

    This error indicates that the 55AA signature is missing from the Boot Sector.  This may be replaced using DskProbe or by using the “Repairing the Boot Sector” section below.

    ·         NTLDR is missing

    Use the “Repairing the NTLDR file” section below.

    ·         Disk error (FAT only)

    Indicates that NTLDR is located on a bad sector.

    ·         A disk read error occurred (NTFS only)

    Indicates that NTLDR is on a bad sector.  Use the “Repairing the NTLDR file” section below.

    ·         NTLDR is compressed

    Indicates that NTLDR is compressed.  Uncompress or replace NTLDR.  Note:  This error is rare.

    ·         Computer boots to a black screen with blinking cursor

    Could be an issue with the MBR or the active partition’s boot code (Q228734).  Use the appropriate section below.

     

    Repairing the MBR

    Use the FIXMBR command from the Windows Recovery Console to re-write the boot code located in the first 446 bytes of the MBR, but to leave the partition table intact.

     

    326215  How To Use the Recovery Console on a Windows Server 2003-Based Computer That Does Not Start

    http://support.microsoft.com/default.aspx?scid=kb;EN-US;326215

     

    WARNING:  DO NOT use this method if you are receiving “Operating System not found” or other BIOS-specific error.  FIXMBR will zero out the partition table if the 55AA signature is missing from the MBR.  The data will be unrecoverable.

     

    Repairing the Boot Sector

    Use the FIXBOOT command from the Windows Recovery Console to write a new Boot Sector to the system partition.

     

    326215  How To Use the Recovery Console on a Windows Server 2003-Based Computer That Does Not Start

    http://support.microsoft.com/default.aspx?scid=kb;EN-US;326215

     

    If you are not able to repair the Boot Sector by using this method, you may repair it manually using the following knowledge base article:

     

    Q153973 Recovering NTFS Boot Sector on NTFS Partitions

    http://support.microsoft.com/default.aspx?scid=kb;EN-US;Q153973

     

    Repairing the NTLDR file

    Use the Recovery Console to copy NTLDR from \i386 directory of the Windows CD-ROM to the root of the hard drive.

     

    Unable to boot using floppy

    If you are unable to start the computer with a boot floppy and you are not receiving an error message, then the problem is most likely with your partition tables.  If invalid partitions are present and you are unable to start your computer with a boot disk, formatting the disk, reinstalling Windows and restoring from backup may be your only option.  It may be possible to recreate the partition table using DskProbe if a backup of the partition information is available.  It also may be possible to manually reconstruct the partition table however this is outside the scope of this blog post.  We may cover this later.

     

    If you do not have a current backup of the data on the computer, as a last resort a data recovery service may be able to recover some of your information. 

     

    Helpful knowledge base articles:

                    Q272395 Error Message: Boot Record Signature AA55 Not Found

                    http://support.microsoft.com/default.aspx?scid=kb;EN-US;Q272395

     

                    Q155892 Windows NT Boot Problem: Kernel File Is Missing From the Disk

                    http://support.microsoft.com/default.aspx?scid=kb;EN-US;Q155892

     

                    Q228004 Changing Active Partition Can Make Your System Unbootable

                    http://support.microsoft.com/default.aspx?scid=kb;EN-US;Q228004

     

                    Q155053 Black Screen on Boot

                    http://support.microsoft.com/default.aspx?scid=kb;EN-US;Q155053

     

                    Q314503 Computer Hangs with a Black Screen When You Start Windows

                    http://support.microsoft.com/default.aspx?scid=kb;EN-US;Q314503

     

                    Q153973 Recovering NTFS Boot Sector on NTFS Partitions

                    http://support.microsoft.com/default.aspx?scid=kb;EN-US;Q153973

     

    Okay boys & girls, that’s it for now.  Next time, I’ll continue with the boot sequence and cover the Boot Loader phase.  This is where things really get interesting… J

     

  • Ntdebugging Blog

    Easily Resolving an Event Viewer Error using a Process Memory Dump

    • 11 Comments

    My name is Ryan Mangipano (ryanman) and I am a Sr. Support Escalation Engineer at Microsoft.  Today I will be blogging about how I used the SOS  .Net Framework debugging extension (and !analyze -v) to easily troubleshoot a .Net Framework exception. This exception was preventing Event Viewer from displaying properly. Event Viewer was returning an error that provided very little information about what was actually causing the issue. I will demonstrate how, in this case, it was very easy to use windbg to obtain information about what went wrong. I did not have to perform a live debug on the issue.  Instead, I used a process dump to obtain very exact information, which was returned by the debugger, relating to the root cause. I was then able to use Process Monitor to identify the file that needed to be examined. These actions led me to the source of the problem, which was easily corrected. Also, the issue discussed in this blog was easily reproduced on Windows Server 2008. This means that you should be able to practice this debug exercise, on your non-production Windows 2008 SP1 Server, for learning purposes if you are interested in doing so.

     

    Issue Reported:  The following error was encountered when opening eventvwr.msc (Event Viewer) on a Windows 2008 Server system:

     

                           "MMC could not create the snap-in."

    MMC could not create the snap-in.

    The snap-in might not have been installed correctly

    Name: Event Viewer

                   CLSID: FX:{b05566ad-fe9c-4363-be05-7a4cbb7cb510}

    clip_image001

    First Step- Research & Data Gathering: After ensuring I first understood the problem reported, I searched for known issues. I found out that we have seen this error before.  It may occur when the following registry key gets deleted or corrupted:

     

                    HKLM\software\Microsoft\MMC\SnapIns\FX:{ b05566ad-fe9c-4363-be05-7a4cbb7cb510}

     

    I had the customer export this key and found that it was not corrupted in any way. I verified that all data was as expected

     

    Next,  a memory dump of the mmc.exe process was collected.  The mmc.exe process is used to host the eventvwr.msc snap-in. This was easily obtained using the built in Windows 2008 Server "Windows Task Manager" feature: "Create Dump File" . If you have several mmc console instances executing on your system, you can use the Task Manager context menu shortcuts "Switch To" and "Go To Process" to help you to identify the correct instance.

    clip_image002clip_image003

    clip_image004

     

    Note: We also collected a process monitor logfile during the startup of eventvwr.msc. This log file later proved very helpful in resolving the issue (as I will show below). Process monitor can be obtained at the following URL:  http://technet.microsoft.com/en-us/sysinternals/bb896645.aspx

     

     

     Now let's have a look at the debug.

     

    1.          First, I navigated Windows Explorer to the location of the dump file and double-clicked it to open it in windbg.exe.

    clip_image005

    It opened in windbg because I had previously run the command windbg -IA, which associates .dmp files with windbg. You can read more about the command line options in windbg in the help file that is included with the debugging tools.

    clip_image002[5]

    clip_image002[9]

    2.            I noticed the following output from the debugger after it loaded the dump file:

     

    This dump file has an exception of interest stored in it.

    The stored exception information can be accessed via .ecxr.

    (ff8.a2c): CLR exception - code e0434f4d (first/second chance not available)

     

     

    3.            Next, I wanted to ensure my symbol path was set correctly. I could have set it using the .sympath command:

     

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

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

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

    0:011> .sympath

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

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

     

    However, when your goal is to simply point to the default symbol server, .symfix is a very nice shortcut. It prevents one from having to try to remember the URL.  Here’s the syntax: 

     

    0:011> .symfix c:\websymbols

    0:011> .sympath

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

     

    4.            To ensure that I didn't waste time reviewing the wrong data, I performed a quick check to ensure that we collected a dump of the requested snap-in.

     

    0:005> !peb

    PEB at 000007fffffdb000

    ....

       CommandLine:  '"C:\Windows\system32\mmc.exe" "C:\Windows\system32\eventvwr.msc" '

     

    You could alternatively dump the  CommandLine from the nt!_PEB using the dt command

     

    0:005> dt nt!_PEB ProcessParameters->CommandLine 000007fffffdb000

    ntdll!_PEB

       +0x020 ProcessParameters              :

          +0x070 CommandLine                    : _UNICODE_STRING ""C:\Windows\system32\mmc.exe" "C:\Windows\system32\eventvwr.msc" "

     

    5.            Next, I then dumped out all of the threads in this process and found the following thread contained a stack that was raising a .Net Framework exception

     

    0:011> ~* kL

    ... (ommitted the non-relevent threads)

     

    # 11  Id: ff8.a2c Suspend: 1 Teb: 7ffd3000 Unfrozen

    ChildEBP RetAddr 

    0691f03c 7343a91c kernel32!RaiseException+0x58

    0691f09c 7343d81a mscorwks!RaiseTheExceptionInternalOnly+0x2a8

    *** WARNING: Unable to verify checksum for MMCEx.ni.dll

    0691f140 6bfe0b5a mscorwks!JIT_Rethrow+0xbf

    *** WARNING: Unable to verify checksum for mscorlib.ni.dll

    0691f1e8 69926cf6 MMCEx_ni+0xd0b5a

    0691f1f4 6993019f mscorlib_ni+0x216cf6

    0691f208 69926c74 mscorlib_ni+0x22019f

    0691f220 733d1b4c mscorlib_ni+0x216c74

    0691f230 733e21b1 mscorwks!CallDescrWorker+0x33

    0691f2b0 733f6501 mscorwks!CallDescrWorkerWithHandler+0xa3

    0691f3e8 733f6534 mscorwks!MethodDesc::CallDescr+0x19c

    0691f404 733f6552 mscorwks!MethodDesc::CallTargetWorker+0x1f

    0691f41c 7349d803 mscorwks!MethodDescCallSite::CallWithValueTypes+0x1a

    0691f604 733f845f mscorwks!ThreadNative::KickOffThread_Worker+0x192

    0691f618 733f83fb mscorwks!Thread::DoADCallBack+0x32a

    0691f6ac 733f8321 mscorwks!Thread::ShouldChangeAbortToUnload+0xe3

    0691f6e8 733f84ad mscorwks!Thread::ShouldChangeAbortToUnload+0x30a

    0691f710 7349d5d4 mscorwks!Thread::ShouldChangeAbortToUnload+0x33e

     

    6.            Out of curiosity, I also ran the Get Last Error command

     

    0:011> !gle

    LastErrorValue: (Win32) 0 (0) - The operation completed successfully.

    LastStatusValue: (NTSTATUS) 0 - STATUS_WAIT_0

     

    7.            After this, I ran analyze -v to see what helpful information the debugger would provide. The debugger did output exception information but informed me that I needed to use the x86 debugger instead.

     

    0:011> !analyze -v

    ...

                            EXCEPTION_RECORD:  ffffffff -- (.exr 0xffffffffffffffff)

                            ExceptionAddress: 771a42eb (kernel32!RaiseException+0x00000058)

                              ExceptionCode: e0434f4d (CLR exception)

                              ExceptionFlags: 00000001

                            NumberParameters: 1

                            Parameter[0]: 80131604

                            MANAGED_BITNESS_MISMATCH:

                                                    Managed code needs matching platform of sos.dll for proper analysis. Use 'x86' debugger.

                            FAULTING_THREAD:  00000a2c

                                                    PRIMARY_PROBLEM_CLASS:  CLR_EXCEPTION

     

    8.            I fired up the x86 debugger and loaded the appropriate version of the SOS .Net Framework debugger extension.  This extension ships in the Operating System along with the .Net Framework.  On most occasions, I would have initiated the loading of the extension through the use of the following syntax:

     

     0:011> .load C:\Windows\Microsoft.NET\Framework\v2.0.50727\sos.dll

     

    OR

     

    0:011> .load  c:\Windows\Microsoft.NET\Framework64\v2.0.50727\sos.dll

     

    However, once you realize that managed debugging will be necessary and that you need the services of the SOS extension, it’s best to use the .loadby command rather than .load.  This is due to the fact that the version of SOS must match the version of the CLR loaded into that process.  Here’s the recommended syntax: 

     

                            0:011>.loadby sos mscorwks

     

    I always verify that my extensions are loaded properly by using the  .chain command.

     

    0:011> .chain

    ...   Extension DLL chain:

                            C:\Windows\Microsoft.NET\Framework\v2.0.50727\sos.dll: image 2.0.50727.1434, API 1.0.0, built Wed Dec 05 22:42:38 2007

     

    9.            Running !help printed out the following helpful information about the SOS extension since sos.dll was at the top of the .chain output:

     

    0:011> !help

    -------------------------------------------------------------------------------

    SOS is a debugger extension DLL designed to aid in the debugging of managed

    programs. Functions are listed by category, then roughly in order of

    importance. Shortcut names for popular functions are listed in parenthesis.

    Type "!help <functionname>" for detailed info on that function.

     

    Object Inspection                  Examining code and stacks

    -----------------------------      -----------------------------

    DumpObj (do)                       Threads

    DumpArray (da)                     CLRStack

    DumpStackObjects (dso)             IP2MD

    DumpHeap                           U

    DumpVC                             DumpStack

    GCRoot                             EEStack

    ObjSize                            GCInfo

    FinalizeQueue                      EHInfo

    PrintException (pe)                COMState

    TraverseHeap                       BPMD

     

    10.            Using the exception address, displayed by the debugger when opening the dump, and the !pe command listed above, I obtained more information about the exception:

                   

    0:011> !pe 771a42eb

    Invalid object

    There are nested exceptions on this thread. Run with -nested for details

     

    0:011> !pe -nested 771a42eb

    Invalid object

     

    Nested exception -------------------------------------------------------------

    Exception object: 040a676c

    Exception type: System.Reflection.TargetInvocationException

    Message: Exception has been thrown by the target of an invocation.

    InnerException: System.Reflection.TargetInvocationException, use !PrintException 040a6a20 to see more

    StackTrace (generated):

        SP       IP       Function

     

    StackTraceString: <none>

    HResult: 80131604

     

    0:011> !PrintException 040a6a20

    Exception object: 040a6a20

    Exception type: System.Reflection.TargetInvocationException

    Message: Exception has been thrown by the target of an invocation.

    InnerException: System.Configuration.ConfigurationErrorsException, use !PrintException 040a6cf8 to see more

    StackTrace (generated):

    <none>

    StackTraceString: <none>

    HResult: 80131604

    There are nested exceptions on this thread. Run with -nested for details

     

    0:011> !PrintException 040a6cf8

    Exception object: 040a6cf8

    Exception type: System.Configuration.ConfigurationErrorsException

    Message: Configuration system failed to initialize

    InnerException: System.Configuration.ConfigurationErrorsException, use !PrintException 040a7174 to see more

    StackTrace (generated):

    <none>

    StackTraceString: <none>

    HResult: 80131902

    There are nested exceptions on this thread. Run with -nested for details

     

    0:011> !PrintException 040a7174

    Exception object: 040a7174

    Exception type: System.Configuration.ConfigurationErrorsException

    Message: Unrecognized configuration section system.web/myInvalidData  

    InnerException: <none>

    StackTrace (generated):

    <none>

    StackTraceString: <none>

    HResult: 80131902

    There are nested exceptions on this thread. Run with -nested for details

     

    11.            Based on the exception information listed above, it appeared that a .Net Framework configuration section, system.web, contained an invalid configuration section named myInvalidData  inside of it. I then re-ran !analyze -v against the dump again (now that I had loaded the x86 debugger) and found that !analyze -v will load the sos.dll extension and even run the !pe extension automatically. It then automatically displayed the exception record information for me as well. Also, notice that the thread listed by !analyze -v matches the thread I examined earlier.

     

                0:011> !analyze -v

                    ...

                            EXCEPTION_MESSAGE:  Unrecognized configuration section system.web/myInvalidData.

                                                    MANAGED_OBJECT_NAME:  System.Configuration.ConfigurationErrorsException

                                                    FAULTING_THREAD:  00000a2c

     

    0:011> ~

       0  Id: ff8.c84 Suspend: 1 Teb: 7ffdf000 Unfrozen

       1  Id: ff8.96c Suspend: 1 Teb: 7ffde000 Unfrozen

       2  Id: ff8.d10 Suspend: 1 Teb: 7ffdd000 Unfrozen

       3  Id: ff8.d94 Suspend: 1 Teb: 7ffdc000 Unfrozen

       4  Id: ff8.a14 Suspend: 1 Teb: 7ffda000 Unfrozen

       5  Id: ff8.fbc Suspend: 1 Teb: 7ffd9000 Unfrozen

       6  Id: ff8.f88 Suspend: 1 Teb: 7ffd8000 Unfrozen

       7  Id: ff8.a64 Suspend: 1 Teb: 7ffd6000 Unfrozen

       8  Id: ff8.bf8 Suspend: 1 Teb: 7ffd5000 Unfrozen

       9  Id: ff8.d24 Suspend: 1 Teb: 7ffd4000 Unfrozen

      10  Id: ff8.ff0 Suspend: 1 Teb: 7ffd7000 Unfrozen

    . 11  Id: ff8.a2c Suspend: 1 Teb: 7ffd3000 Unfrozen

     

    12. At this point I was interested in identifying the source of this unrecognized configuration. Instead of engaging our .Net support team, I started with a quick search using www.live.com for     

     

                "unrecognized configuration section" system.web site:microsoft.com

                 

    This returned the following results http://search.live.com/results.aspx?q=%22unrecognized+configuration+section%22+system.web+site%3Amicrosoft.com&form=QBRE

     

    By quickly reviewing some of the hits returned, I found that others had encountered this exception in their own applications.  This is due to invalid entries in the various .config  files used in .Net. Looking through the posts, different configuration file names and paths were observed.

     

    So, I opened up the process monitor logfile to see which configuration files we were reading data from. I added filter criterion to match entries from the mmc.exe process, the TID from the FAULTING_THREAD listed in the exception data, path data containing .config,  and a successful status result. It's best to be as specific as possible.

     

    clip_image002[7]

    I found that we were reading in a large amount of settings over and over again from the .net Framework global configuration file:             

                                    c:\Windows\Microsoft.NET\Framework\v2.0.50727\CONFIG\machine.config

                    (on x64 this would be     C:\Windows\Microsoft.NET\Framework64\v2.0.50727\CONFIG\machine.config)

    clip_image002[11]

    Final Step- Putting it all together, Reproducing the issue, & confirming resolution : Using notepad, a quick search of the suspect xml file (C:\Windows\Microsoft.NET\Framework64\v2.0.50727\CONFIG\machine.config) on my system revealed a <system.web> section. At this point, I suspected that this section contained an invalid section which may have been related to the problem. To verify this, and since I like to break things, I added an invalid configuration setting <myInvalidData/> to my global configuration file. Doing so, I successfully reproduced the issue on my system. I then contacted the customer and asked if they had by any chance added any settings under the <system.web> in the configuration file: c:\Windows\Microsoft.NET\Framework\v2.0.50727\CONFIG\machine.config.

     

    The customer informed me that, per the request of their ASP.net developer, they had in fact added settings to that section of the file.  By researching http://msdn.microsoft.com/en-us/library/system.web.aspx and the schema documentation at http://msdn.microsoft.com/en-us/library/dayb112d.aspx, we were able to determine that the settings that were present in this file should not have been present inside of <system.web> . The settings were moved to the proper location per the developer and the issue was resolved.

     

    Here are the steps I used to reproduce the issue in case you are attempting to replicate this at home-

     

    A. Using notepad, open the following configuration file on a non-production Windows Server 2008 SP1 system:

         (please make a backup copy first in case you make a mistake)  

       c:\Windows\Microsoft.NET\Framework\v2.0.50727\CONFIG\machine.config

         OR   (Open the version that matches the architecture of your platform )

       C:\Windows\Microsoft.NET\Framework64\v2.0.50727\CONFIG\machine.config

     

    clip_image012

    B. Find the section <system.web> in this file (you can use the find function in notepad):

    clip_image013

    C.  Add the following line directly after <system.web> as shown in the example below:

                         <myInvalidData/>   

    clip_image014

    D. Save the file and then open eventvwr.msc and verify that the following error is displayed:

    clip_image015

    Conclusion

    Hopefully this blog has demonstrated an example of how you can use the "create dump file" feature of Windows 2008, windbg, and other related tools in an attempt to gain more specific data when your error message is not revealing the source of the problem. Feel free to post any questions, comments, or concerns.

     

Page 2 of 23 (230 items) 12345»