LogParser did it again: application pool recycle

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