This started as a “standard” w3wp.exe crash, but this time IIS was also randomly disabling one of the application pools on the server. This is a protection mechanism we have since IIS 6 called Rapid Fail Protection that disables ad application pool (for security and stability reasons) if it fails (encounters severe errors) too often: how often and how much time it’s configurable (see Configuring Rapid-Fail Protection in IIS 6.0), the default is 5 failures in 5 minutes.
Looking at the System event log there were plenty of messages like:
A worker process with process id of 'xxx' serving application pool 'MyAppPool' has requested a recycle because it reached its virtual memory limit.
And also:
A process serving application pool 'MyAppPool' exceeded time limits during shut down. The process id was 'xxx'.
How often? As usual, LogParser comes at hand.
logparser "select quantize(TimeGenerated, 300) as TimeGen, count(*) as NumberOfrecycles into memory_limit_recycles.log from system.evt where EventID = 1077 and Message like '%\'MyAppPool%' group by TimeGen order by TimeGen" -i:evt -o:nat -rtp:-1
Note the “quantize” function: LogParser help states “Truncates a value to the nearest multiple of another value”; what it actually does in the command above is count the number of recurrences of a certain event in “blocks” of 5 minutes (300 seconds in my sample).
The output is something like:
Generated NumberOfRecycles ------------------- ---------------- 2008-07-06 21:55:00 5 2008-07-06 22:00:00 5 2008-07-06 22:05:00 5 2008-07-06 22:10:00 4 2008-07-06 22:15:00 4 2008-07-06 22:20:00 3 2008-07-06 22:25:00 1 2008-07-06 22:30:00 2 2008-07-06 22:35:00 1 2008-07-06 22:40:00 2 2008-07-06 22:45:00 1 2008-07-06 22:50:00 2 2008-07-06 22:55:00 1 2008-07-06 23:00:00 2 2008-07-06 23:05:00 1 2008-07-06 23:10:00 2 2008-07-06 23:15:00 1 2008-07-06 23:20:00 2 2008-07-06 23:25:00 1 2008-07-06 23:30:00 2 2008-07-06 23:35:00 3 [...]
As you can see the pool is recycled quite often, event 4-5 times every 5 minutes, exactly the default limit configured for pool heal checking in IIS… Moreover we don’t have to forget about the second error message:
logparser "select quantize(TimeGenerated, 300) as TimeGen, count(*) as ShutDownLimit into ShutDownLimit.log from system.evt where Message like '%\'MyAppPool%' and Message like '%exceeded time limits during shut down%' group by TimeGen order by TimeGen" -i:evt -o:nat -rtp:-1
And the output is:
TimeGen ShutDownLimit ------------------- ----- 2008-07-09 09:05:00 3 2008-07-09 10:00:00 5 2008-07-11 14:40:00 3 2008-07-15 10:50:00 5 2008-07-15 11:30:00 3 2008-07-15 13:00:00 3 2008-07-15 14:45:00 3 2008-07-15 14:50:00 4 2008-07-15 14:55:00 3 2008-07-15 16:15:00 3 2008-07-15 16:20:00 4 2008-07-15 16:40:00 3 2008-07-15 16:45:00 3 2008-07-15 17:00:00 3 2008-07-15 17:25:00 3 2008-07-15 17:30:00 3 2008-07-15 17:40:00 3 2008-07-15 17:45:00 3 2008-07-15 17:55:00 3 2008-07-15 18:00:00 4
Sometimes we’re clearly exceeding the configured pool health checking so really no surprise IIS disables it.
But why the pool is recycled so often? Well, we found a mistake in customer’s configuration: the application pool was configured to be recycled when the virtual memory reached 50 Mb, definitely a value too low. Increasing it to resolved also this problem: no more pool recycles and as obvious side effect the users noticed an increased stability and performance when working with the application.
Carlo
The time-taken field is quite handy if your web application or IIS web server is performing poorly (or slower that you expect) or even for simple statistics and monitoring purposes, if you want to keep under how long it takes every web request to be processed and the page sent back to the client.
In earlier versions of IIS the time-taken field was not selected by default so I often had to request customers to first enable it, wait some more time for the problem to reoccur (to give IIS the change to create a significant amount of logs with the new value) before being able to start troubleshooting. Well, at least before being able to extract some statistics involving the duration of web requests.
Luckily in IIS 7 time-taken is now selected by default so we already it logged and ready to use.
Taken from the IIS online docs, here is the meaning each field in IISW3C logs:
Client IP Address (c-ip)
Note: The host name that you configure for your Web site might appear differently in the log files because HTTP.sys logs host names by using the punycode-encoded format.
What does time-taken actually measures? It measures the length of time that it takes for a request to be processed. The client-request time stamp is initialized when HTTP.sys receives the first byte of the request. HTTP.sys is the kernel-mode component that is responsible for HTTP logging for IIS activity. The client-request time stamp is initialized before HTTP.sys begins parsing the request. The client-request time stamp is stopped when the last IIS response send completion occurs. Beginning in IIS 6.0, the time-taken field typically includes network time. Before HTTP.sys logs the value in the time-taken field, HTTP.sys usually waits for the client to acknowledge the last response packet send operation or HTTP.sys waits for the client to reset the underlying TCP connection. Therefore, when a large response or large responses are sent to a client over a slow network connection, the value of the time-taken field may be more than expected.
If you are either troubleshooting or just monitoring your site/IIS, LogParser can be extremely useful to elaborate statistics and charts out of your IIS logs, find average and peak execution time for your pages and web services etc…
For example if you want to get the average execution time for your .aspx (or .asmx) pages/services you can run something like:
logparser "SELECT AVG(time-taken) As AverageTimeTaken, MAX(time-taken) As MaxTimeTaken, COUNT(*) As Hits, TO_LOWERCASE(cs-uri-stem) As Uri INTO average_uri_execution_time.log FROM ex*.log WHERE EXTRACT_EXTENSION(TO_LOWERCASE(cs-uri-stem)) = %1 GROUP BY TO_LOWERCASE(cs-uri-stem) ORDER BY AverageTimeTaken DESC" -i:IISW3C -o:TSV
Note: the command must be placed on a single line, I split it here just to be easier to read
Using the IISW3C input format, if you have your logs organized in subfolders you can parse them all at once appending “-recurse:-1” to the command above.
Here you can get the top n slowest pages to complete:
logparser "SELECT TOP 100 time-taken, cs-uri-stem INTO top_time_taken.log FROM ex*.log WHERE extract_extension(to_lowercase(cs-uri-stem)) = 'aspx' ORDER BY time-taken DESC" -i:iisw3c -o:tsv
If you are interested only on a specific timeframe (say you had a load pick and want to know more) you can take the cue from here:
logparser "SELECT AVG(time-taken) As AverageTimeTaken, MAX(time-taken) As MaxTimeTaken, COUNT(*) As Hits, TO_LOWERCASE(cs-uri-stem) As Uri INTO date_range.txt FROM *.log WHERE TO_TIMESTAMP(date,time) BETWEEN TIMESTAMP('2008/05/27 10:11:00', 'yyyy/MM/dd hh:mm:ss') AND TIMESTAMP('2008/05/27 10:13:00', 'yyyy/MM/dd hh:mm:ss') GROUP BY TO_LOWERCASE(cs-uri-stem)" -i:IISW3C -RECURSE:-1 -o:NAT -RTP:-1
If you want an overview of resource types served by your IIS (with resource I mean every file extension IIS logs) you can use something like this:
logparser "select to_lowercase(extract_extension(cs-uri-stem))as ResourceType, MIN(time-taken) as MinTimeTaken, MAX(time-taken) as MaxTimeTaken, AVG(time-taken) as AvgTimeTaken, COUNT(*) as Hits INTO timers.txt FROM time-taken.log GROUP BY ResourceType" -i:IISW3C -o:NAT -RTP:-1
A few words about the load you add on the serve enabling additional fields for IIS logs: the default files are essentially the same in IIS 6 and 7 except for time-taken which is now enabled by default on IIS 7. This suggests the load you’ll add to the server is negligible, but as always is really depends on your server and application; to stay on the safe side you can add fixed-size fields, for example handle with case the cookie field, enable it if you need to troubleshoot specific problems involving cookies (session mixed-up etc…), otherwise just leave it off.
“Split view” is one of the new features in Visual Studio 2008 web designer: this is the possibility to have Design View and Source View of your page at the same time (see What's New in ASP.NET and Web Development, “Visual Web Developer Enhancements” paragraph). A few days ago a customer called in to report a problem with his Visual Studio and split view: when trying to view a file (even a new one) in split view or design view the IDE either crashed or frozen.
As you can imagine we took a crash dump with adplus, but a first look at the threads, stack, exceptions etc… (the usual stuff) did not show anything interesting. Then I thought to some external process (like an antivirus, third parties add-ons etc…) that might meddle in and had a look at the list of modules loaded within the process with lmf (list loaded modules with full path). There where only a couple of odd dlls loaded, from Office 2003:
33f20000 34118000 FPCUTL (deferred) Image path: C:\Program Files\Microsoft Office\OFFICE11\FPCUTL.DLL Image name: FPCUTL.DLL Timestamp: Wed Jun 06 19:44:55 2007 (4666F297) CheckSum: 001EC356 ImageSize: 001F8000 File version: 11.0.8170.0 Product version: 11.0.8170.0 File flags: 0 (Mask 3F) File OS: 40004 NT Win32 File type: 2.0 Dll File date: 00000000.00000000 Translations: 0409.04e4 CompanyName: Microsoft Corporation ProductName: Microsoft Office 2003 InternalName: FP40CUTL OriginalFilename: FP40CUTL.DLL ProductVersion: 11.0.8170 FileVersion: 11.0.8170 FileDescription: Microsoft Office FrontPage Client Utility Library LegalCopyright: Copyright © 1995-2003 Microsoft Corporation. All rights reserved. 37050000 37157000 OMFC (deferred) Image path: C:\Program Files\Microsoft Office\OFFICE11\OMFC.DLL Image name: OMFC.DLL Timestamp: Fri Apr 13 21:43:21 2007 (461FDD59) CheckSum: 0010A869 ImageSize: 00107000 File version: 11.0.8164.0 Product version: 11.0.8164.0 File flags: 0 (Mask 3F) File OS: 40004 NT Win32 File type: 2.0 Dll File date: 00000000.00000000 Translations: 0000.04e4 CompanyName: Microsoft Corporation ProductName: Microsoft Office 2003 InternalName: OMFC.DLL OriginalFilename: OMFC.DLL ProductVersion: 11.0.8164 FileVersion: 11.0.8164 FileDescription: Microsoft Office MFC LegalCopyright: Copyright © 1993-2003 Microsoft Corporation. All rights reserved.
That rang a bell, especially about fpcutl.dll… This dll comes with both Visual Studio and Office 2003 but the two versions are incompatible: Visual Studio in this case was loading the wrong one. Why?
Well, it happens that Visual Studio looks at the system PATH to load this (and other) component, while Office doesn’t… Here is the PATH value from the dump (use !procinfo and then check the path value):
C:\WINDOWS\system32; C:\WINDOWS; C:\WINDOWS\System32\Wbem; C:\Program Files\Microsoft SQL Server\90\Tools\binn\; C:\Program Files\Microsoft SQL Server\90\DTS\Binn\; C:\Program Files\Microsoft SQL Server\90\Tools\Binn\VSShell\Common7\IDE\; C:\Program Files\Microsoft Visual Studio 8\Common7\IDE\PrivateAssemblies\; C:\PROGRA~1\MICROS~2\OFFICE11
The Office 11 entry is the last one… but there is something wrong anyway, who spots it?
We have an entry for Visual Studio 8 (Visual Studio 2005), but where is the entry for Visual Studio 9 (VS 2008)?
For some reason the PATH value has not been updated (or maybe it has modified after the setup) and we don’t know exactly why; the point is that we need to fix it. A quick search on the machine found three copies of fpcutl.dll:
We added the missing folders at the beginning of the PATH string which now reads as:
C:\Program Files\Microsoft Web Designer Tools\VWD; C:\Program Files\Microsoft Visual Studio 9.0\Common7\IDE; C:\Program Files\Microsoft Visual Studio 9.0\VC\BIN; C:\Program Files\Microsoft Visual Studio 9.0\Common7\Tools; C:\Windows\Microsoft.NET\Framework\v3.5; C:\Windows\Microsoft.NET\Framework\v2.0.50727; C:\Program Files\Microsoft Visual Studio 9.0\VC\VCPackages; C:\WINDOWS\system32; C:\WINDOWS; C:\WINDOWS\System32\Wbem; C:\Program Files\Microsoft SQL Server\90\Tools\binn\; C:\Program Files\Microsoft SQL Server\90\DTS\Binn\; C:\Program Files\Microsoft SQL Server\90\Tools\Binn\VSShell\Common7\IDE\; C:\Program Files\Microsoft Visual Studio 8\Common7\IDE\PrivateAssemblies\; C:\PROGRA~1\MICROS~2\OFFICE11
The most important one on this case is “C:\Program Files\Microsoft Web Designer Tools\VWD”: Visual Studio will look into this folder to load the right version of fpcutl.dll (PATH is a first in – first serve list of folders, the first match will be the one we use) and Office continues working happily anyway.