The Case of the Mysteriously Large Spooler.xml File

Hi AskPerf readers, Don Geddes here again.  Today we’re going to look at Windows Error Reporting logging in Windows Server 2008 and how it can affect the Printing subsystem.  There was a KB article written a while back that discussed the Windows Error Reporting service logging and how it was changed with Windows Server 2003 Service Pack 1. Here is a link to the article for reference: KB890402 – Windows Server 2003 SP1 and x64-based versions of Windows Server 2003 increase the amount of information that is logged by the Windows Error Reporting Service after a print spooler crash.

This article explained that after Service Pack 1 was installed, more information would be logged by the Windows Error Reporting service after a print spooler crash.  The article also explains how to disable this feature by using the registry key DisableWERLogging.

Now that Windows Server 2008 has shipped, we have seen a few cases where a print spooler is entering into an error condition that is not serious enough to cause a spooler crash but is still captured by Windows Error Reporting.  It turns out that the logging is enabled by default (as it has been since Windows Server 2003 SP1) and if you have a very busy print server or are stress testing a print server, you can run into a situation where you see high CPU utilization on the spoolsv.exe process.  To make matters worse, the errors are logged into a file named spooler.xml that is written to the %windir%\system32\spool folder.  This file is not currently limited in size, and if your server is busy enough and hitting these error conditions frequently enough, you can also fill up your hard drive as the spooler.xml file continues to grow unchecked.

So how do you recognize this and how can you fix it?  If you dump the spooler process using ADPLUS and load it into the debugger, you can use the !runaway command to find the thread that has been spinning, and then dump that thread to see what it is doing.  Using public symbols you should be able to see something similar to the following:

0:000> !runaway
 User Mode Time
  Thread       Time
  17:1fe4      10 days 13:15:32.197
  15:41c       1 days 15:42:16.103
   4:25c       0 days 11:12:53.199
   0:720       0 days 0:02:05.268
  11:384       0 days 0:01:01.823
  10:20c       0 days 0:00:59.592
   2:728       0 days 0:00:50.513
   5:288       0 days 0:00:00.624
   8:304       0 days 0:00:00.062
   3:730       0 days 0:00:00.046
  16:10a4      0 days 0:00:00.000
  14:394       0 days 0:00:00.000
  13:340       0 days 0:00:00.000
  12:2e8       0 days 0:00:00.000
   9:2c0       0 days 0:00:00.000
   7:27c       0 days 0:00:00.000
   6:280       0 days 0:00:00.000
   1:724       0 days 0:00:00.000

0:000> ~17kb
ChildEBP RetAddr  Args to Child              
04a3f684 76862046 768e09b8 725ec060 00000000 msvcrt!_woutput_l+0x104
04a3f6cc 725ebe9d 768e09b8 725ec060 00000000 msvcrt!fwprintf+0x68
04a3f6ec 725eb59f 00000005 768e09b8 02230968 win32spl!NCSRCache::TCacheAttribute::Display+0x8d
04a3f70c 725eabe8 00000004 768e09b8 04a3f738 win32spl!NCSRCache::TCacheEntryImp::Display+0xc4
04a3f71c 725e5393 02230968 00000004 768e09b8 win32spl!NCSRCache::TCacheEntry::Display+0x1f
04a3f738 725f12cf 00000002 02230968 00000000 win32spl!TCSRCacheWalk::PreOrderProcess+0x38
04a3f754 725c0675 00000002 02230968 00000001 win32spl!NCSRCommon::TCacheWalker::Process+0x32
04a3f788 725f12ec 00000002 00000001 00000000 win32spl!NCSRCommon::TCacheWalker::Descend+0x77
04a3f7a4 725c0675 00000001 0223e7f8 00000000 win32spl!NCSRCommon::TCacheWalker::Process+0x4f
04a3f7d8 725f12ec 00000001 00000002 00000000 win32spl!NCSRCommon::TCacheWalker::Descend+0x77
04a3f7f4 725c0675 00000000 0223e728 725b4e08 win32spl!NCSRCommon::TCacheWalker::Process+0x4f
04a3f828 725b505b 00000000 00000001 725b4f5f win32spl!NCSRCommon::TCacheWalker::Descend+0x77
04a3f834 725b4f5f 00000000 02537f90 7756cbe0 win32spl!NCSRCommon::TCacheWalker::Iterate+0xa
04a3f87c 731313d9 00000001 768e09b8 00000000 win32spl!TCSRWerLogger::EnumAndLogCSRCache+0xd1
04a3f8bc 7313061a 00000000 0226a5c0 0221e33c spoolss!LogSpoolerObjects+0x6d
04a3f8d0 73130687 7756b8fc 05cbae28 0221e480 spoolss!TWerLogWorkItem::Run+0x52
04a3f8e4 7756cbb4 04a3f944 0221e480 05cbae28 spoolss!NThreadingLibrary::TWorkCrew::tpTimerCallback+0x4a
04a3f908 7756de3f 04a3f944 05cbae88 73fc3417 ntdll!TppTimerpExecuteCallback+0x14d
04a3fa38 76934911 00409688 04a3fa84 7756e4b6 ntdll!TppWorkerThread+0x545
04a3fa44 7756e4b6 00409688 73fc34ab 00000000 kernel32!BaseThreadInitThunk+0xe

Fixing this problem condition requires the same workaround as described in the article above. The option to include the additional information for the spooler in the WER log is controlled by the following registry subkey: HKEY_LOCAL_MACHINE\System\CurrentControlSet\Control\Print\DisableWERLogging.  The additional information that is included in the WER log does not affect the server performance or exhibit any other abnormal behavior on the system.

By default, the option to include the additional information in the Windows Error Reporting log is enabled. When this option is enabled, the registry entry has the value of 0.

  1. Click Start, click Run, type regedit, and then click OK.
  2. Expand the following subkey: HKEY_LOCAL_MACHINE\System\CurrentControlSet\Control\Print
  3. Create a new DWORD Value, and then type DisableWERLogging in the New Value field.
  4. Right-click the DisableWERLogging registry entry, and then click Modify.
  5. In the Value data box, type 1, and then click OK.

Make sure you stop and restart the print spooler at this point and delete the spooler.xml file if it has managed to chew up a great deal of hard drive space, and then consider the case of the mysteriously large spooler.xml file closed.

And with that we’ve reached the end of this post.  See you next time.

Don Geddes

Share this post :