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:
| 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: |
| 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