IIS 5 and 6 time-taken field

While checking the performance problem a client was having with a legacy ASP.NET 1.1 application (yep, I am still young enough to call a 6 years old system, legacy J ), I asked myself what seems like a basic question.

Does the time-taken column in IIS 5 logs takes into account the network time ?

That is, Is the stop watch stopped when the response is ready or when the last TCP acknowledge is received from the client. After googling for a while I was quite disappointed by the lack of information regarding this specific column. The only useful information I found concerned IIS 6 and were …hum, let’s just say that Microsoft doesn’t seems to be able to make up its mind about this field:

According to :http://support.microsoft.com/kb/944884

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.

According to :http://www.microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/676400bc-8969-4aa7-851a-9319490a9bbb.mspx?mfr=true

For the time-taken field, the client-request timestamp is initialized when HTTP.sys receives the first byte, but before HTTP.sys begins parsing the request. The client-request timestamp is stopped when the last IIS send completion occurs. Time taken does not reflect time across the network. The first request to the site shows a slightly longer time taken than other similar requests because HTTP.sys opens the log file with the first request.

Perplexed, I figured out I could know the answer for sure by firing up Fiddler and comparing Fiddler time with the value of the time-taken columns in IIS log. I had limited access to the client environment but managed to get some measures nonetheless. Once again, it was a dead-end, the Fiddler times were sometimes higher than the IIS log time, sometimes lower.

That’s when I decided to contact the Microsoft Partner Support.

The definite answer they gave me for the time-taken field in IIS 5 logs is:

Since the calculation includes the time for the acknowledgement from the client, it may be skewed by any network latency issues.

The not so definite answer the support gave me for the IIS 6 time-taken field is that after checking the source code, the network time is not included in the time-taken field. However they also say that that if the request is aborted during its execution, no value are logged for the request; Therefore it would seems like IIS 6 waits for the last ACK to log BUT it doesn’t log the network. And that would be why the public available information is as clear as mud.

I hope it helps.

Edit : 29/06/2009

A reader (thank you Joe) pointed out to me that the http://www.microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/676400bc-8969-4aa7-851a-9319490a9bbb.mspx?mfr=true article as been updated with the following :

This is no longer true for II6, and you can check the KB94483. IIS TIME-TAKEN field takes into account the last ACK from the answer to the response, so in fact does reflect time across the network. There is only 2 exceptions for this:

• The response size is less than or equal to 2 KB, and the response size is from memory.
• TCP buffering is used.

So problem solved, but if anyone find the trace of the KB94483 mentionned, let me know because I can't !