wegee2
asked on
IIS Log Timestamp Question
Using the extended log format in IIS we're given the wonderful "time-taken" field.
Given this entry:
2013-06-03 02:00:00 1.2.3.4 GET /file.htm - 443 - 5.6.7.8 (User Agent) 200 0 0 300000
The time-taken is 300000ms, or 5 minutes.
My question is.. did the request begin at 02:00, or did the request begin at 01:55 and end at 02:00?
A Followup question.. if the timestamp represents the end of the request, are there any log parsers that automatically adjust the timestamp to represent the origin of the request?
Given this entry:
2013-06-03 02:00:00 1.2.3.4 GET /file.htm - 443 - 5.6.7.8 (User Agent) 200 0 0 300000
The time-taken is 300000ms, or 5 minutes.
My question is.. did the request begin at 02:00, or did the request begin at 01:55 and end at 02:00?
A Followup question.. if the timestamp represents the end of the request, are there any log parsers that automatically adjust the timestamp to represent the origin of the request?
ASKER
I meant if the timestamp represented the end of the request, and in that sample the request instead started at 01:55, I wanted to convert it.
If the timestamp is already representing the beginning of the request, no conversion is needed and my followup question is moot.
I am now curious though if a request takes 5 minutes to process, how long does IIS buffer the information before writing to the log file.. since it can't write the "time-taken" until the request has finished. I guess that's another question for another day.
If the timestamp is already representing the beginning of the request, no conversion is needed and my followup question is moot.
I am now curious though if a request takes 5 minutes to process, how long does IIS buffer the information before writing to the log file.. since it can't write the "time-taken" until the request has finished. I guess that's another question for another day.
The time is when the request was received i.e. it is the start time. So in your example the request would have ended at 02:05:00
As for the second part, I'm not 100% sure.
As for the second part, I'm not 100% sure.
ASKER
I did some testing to try and answer the second part, and in doing so I'm afraid I'm going to have to disagree with you on the first part.
Take this log entry from my test:
This test is a specific .asp script I wrote with an infinite loop and a 180 second timeout. I started it as close to 15:18:00 as my mouse-clicking finger could get.
Notice the timestamp is 3 minutes, 15 seconds after when I started it. And look at the time-taken. 194821 is a few ms shy of 3 minutes, 15 seconds.
So I believe the timestamp is the end of the request (and the time of writing to the log file), not the actual start of the request to IIS.
If you have any documentation to both explain this result and assert your idea, please share it, because I sure as heck couldn't find any before I posted the question.
Take this log entry from my test:
2013-06-04 15:21:15 ::1 GET /timeout.asp |-|ASP_0113|Script_timed_out 80 - ::1 (User Agent snipped) 500 0 0 194821This test is a specific .asp script I wrote with an infinite loop and a 180 second timeout. I started it as close to 15:18:00 as my mouse-clicking finger could get.
Notice the timestamp is 3 minutes, 15 seconds after when I started it. And look at the time-taken. 194821 is a few ms shy of 3 minutes, 15 seconds.
So I believe the timestamp is the end of the request (and the time of writing to the log file), not the actual start of the request to IIS.
If you have any documentation to both explain this result and assert your idea, please share it, because I sure as heck couldn't find any before I posted the question.
ASKER CERTIFIED SOLUTION
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
ASKER
Having done more testing and finding the above blog by a MS employee on the subject, I'm content with this answer.
Not sure what you mean by
adjust the timestamp to represent the origin of the request