Time-taken and LogParser for web site statistics


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.

Time Taken logging property in IIS 6

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:

Date (date) Logs the date on which the request occurred. Selected by default
Time (time) Logs the time, in Coordinated Universal Time (UTC), at which the request occurred. Selected by default

Client IP Address (c-ip)

Logs the IP address of the client that made the request. Selected by default.
User Name (cs-username) Logs the name of the authenticated user who accessed the server. Anonymous users are indicated by a hyphen. Selected by default.
Service Name (s-sitename) Logs the Internet service name and instance number that was running on the client at the time that the incident was logged.
Server Name (s-computername) Logs the name of the server on which the log file entry was generated.
Server IP Address (s-ip) Logs the IP address of the server on which the log file entry was generated. Selected by default.
Server Port (s-port) Logs the server port number that is configured for the service. Selected by default.
Method (cs-method) Logs the HTTP method, such as GET, that is used in the request. Selected by default.
URI Stem (cs-uri-stem) Logs the Uniform Resource Identifier (URI) that is the target of the action, such as Default.htm. Selected by default.
URI Query (cs-uri-query) Logs the query, if any, that the client was trying to perform. A URI query is necessary only for dynamic pages. Selected by default.
Protocol Status (sc-status) Logs the HTTP status code. Selected by default.
Protocol Substatus (sc-substatus) Logs the HTTP substatus code. Selected by default.
Win32 Status (sc-win32-status) Logs the Windows status code. Selected by default.
Bytes Sent (sc-bytes) Logs the number of bytes that the server sent.
Bytes Received (cs-bytes) Logs the number of bytes that the server received.
Time Taken (time-taken) Logs the length of time that the action took in milliseconds. Selected by default.
Protocol Version (cs-version) Logs the protocol version, HTTP or FTP, that the client used.
Host (cs-host) Logs the host header name, if any.

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.

User Agent (cs(User-Agent)) Logs the browser from which the request came. Selected by default.
Cookie (cs(Cookie)) Logs the content of the cookie sent or received, if any.
Referer (cs(Referer) ) Logs the site that the user last visited. This site provided a link to the current site.

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.

A few samples

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.

 

Carlo

Quote of the day:

Art is science made clear. – Jean Cocteau

Comments (2)

  1. Jody says:

    "execution time" is a bit of a misnomer for the time-taken field in IIS logs as it also counts network time.  

    "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."

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