IIS Log Time column: Start or End Time?

IIS Log Time column: Start or End Time?

am 18.10.2007 14:57:06 von JimLad

Hi,

In IIS 6.0 Log, does Time represent the end time or the start time?
Doesn't matter much normally, but I have some time-out entries where
time-taken is 6 minutes where it makes a huge difference.

I think the time in the log is the end time, and that to get a rough
approximation of the start time I need to subtract the time-taken. Am
I correct?

Cheers,

James

Re: IIS Log Time column: Start or End Time?

am 18.10.2007 17:02:54 von Ken Schaefer

I believe this is correct. The log entry is one of the last thing performed
for each request

Cheers
Ken

"JimLad" wrote in message
news:1192712226.033895.124230@y27g2000pre.googlegroups.com.. .
> Hi,
>
> In IIS 6.0 Log, does Time represent the end time or the start time?
> Doesn't matter much normally, but I have some time-out entries where
> time-taken is 6 minutes where it makes a huge difference.
>
> I think the time in the log is the end time, and that to get a rough
> approximation of the start time I need to subtract the time-taken. Am
> I correct?
>
> Cheers,
>
> James
>

Re: IIS Log Time column: Start or End Time?

am 19.10.2007 11:48:30 von JimLad

On Oct 18, 4:02 pm, "Ken Schaefer"
wrote:
> I believe this is correct. The log entry is one of the last thing performed
> for each request
>
> Cheers
> Ken
>
> "JimLad" wrote in message
>
> news:1192712226.033895.124230@y27g2000pre.googlegroups.com.. .
>
>
>
> > Hi,
>
> > In IIS 6.0 Log, does Time represent the end time or the start time?
> > Doesn't matter much normally, but I have some time-out entries where
> > time-taken is 6 minutes where it makes a huge difference.
>
> > I think the time in the log is the end time, and that to get a rough
> > approximation of the start time I need to subtract the time-taken. Am
> > I correct?
>
> > Cheers,
>
> > James- Hide quoted text -
>
> - Show quoted text -

Thanks.

Also just to clarify, when you get a new set of headers in the log,
that indicates a website restart or an idle timeout on the worker
process. Is that correct? Could anything else cause new headers to be
written?

Cheers,

James

Re: IIS Log Time column: Start or End Time?

am 19.10.2007 20:46:44 von David Wang

On Oct 19, 2:48 am, JimLad wrote:
> On Oct 18, 4:02 pm, "Ken Schaefer"
> wrote:
>
>
>
>
>
> > I believe this is correct. The log entry is one of the last thing performed
> > for each request
>
> > Cheers
> > Ken
>
> > "JimLad" wrote in message
>
> >news:1192712226.033895.124230@y27g2000pre.googlegroups.com. ..
>
> > > Hi,
>
> > > In IIS 6.0 Log, does Time represent the end time or the start time?
> > > Doesn't matter much normally, but I have some time-out entries where
> > > time-taken is 6 minutes where it makes a huge difference.
>
> > > I think the time in the log is the end time, and that to get a rough
> > > approximation of the start time I need to subtract the time-taken. Am
> > > I correct?
>
> > > Cheers,
>
> > > James- Hide quoted text -
>
> > - Show quoted text -
>
> Thanks.
>
> Also just to clarify, when you get a new set of headers in the log,
> that indicates a website restart or an idle timeout on the worker
> process. Is that correct? Could anything else cause new headers to be
> written?
>
> Cheers,
>
> James- Hide quoted text -
>
> - Show quoted text -


You get a new set of headers whenever HTTP.SYS has to open the log
file to start writing a log entry to it.

What you have mentioned is a subset of possible actions that can cause
new headers to be written. There are others, but without a context, it
is not useful to list them.


//David
http://w3-4u.blogspot.com
http://blogs.msdn.com/David.Wang
//

Re: IIS Log Time column: Start or End Time?

am 22.10.2007 11:47:12 von JimLad

On Oct 19, 7:46 pm, David Wang wrote:
> On Oct 19, 2:48 am, JimLad wrote:
>
>
>
>
>
> > On Oct 18, 4:02 pm, "Ken Schaefer"
> > wrote:
>
> > > I believe this is correct. The log entry is one of the last thing performed
> > > for each request
>
> > > Cheers
> > > Ken
>
> > > "JimLad" wrote in message
>
> > >news:1192712226.033895.124230@y27g2000pre.googlegroups.com. ..
>
> > > > Hi,
>
> > > > In IIS 6.0 Log, does Time represent the end time or the start time?
> > > > Doesn't matter much normally, but I have some time-out entries where
> > > > time-taken is 6 minutes where it makes a huge difference.
>
> > > > I think the time in the log is the end time, and that to get a rough
> > > > approximation of the start time I need to subtract the time-taken. Am
> > > > I correct?
>
> > > > Cheers,
>
> > > > James- Hide quoted text -
>
> > > - Show quoted text -
>
> > Thanks.
>
> > Also just to clarify, when you get a new set of headers in the log,
> > that indicates a website restart or an idle timeout on the worker
> > process. Is that correct? Could anything else cause new headers to be
> > written?
>
> > Cheers,
>
> > James- Hide quoted text -
>
> > - Show quoted text -
>
> You get a new set of headers whenever HTTP.SYS has to open the log
> file to start writing a log entry to it.
>
> What you have mentioned is a subset of possible actions that can cause
> new headers to be written. There are others, but without a context, it
> is not useful to list them.
>
> //Davidhttp://w3-4u.blogspot.comhttp://blogs.msdn.com/David. Wang
> //- Hide quoted text -
>
> - Show quoted text -

Well, I've been looking at a problem, which from the IIS log file
looks like a db server problem (very slow or timeout on data access
via SQLXML virtual directory, fine when just accessing files on web
server). But there is a set of headers at about the same time. I
suspect that this is a manual website restart in an attempt to solve
the problem, but I'd like to be able to confirm that. As far as I am
aware this isn't logged anywhere? There's nothing in the event log,
although get the following about quarter of an hour later (but I think
it's a red herring as the problem had resolved by then):

Application popup: w3wp.exe - Application Error : The instruction at
"0x4bc4ce39" referenced memory at "0x4bc4ce39". The memory could not
be "read".

Re: IIS Log Time column: Start or End Time?

am 22.10.2007 12:11:44 von David Wang

On Oct 22, 2:47 am, JimLad wrote:
> On Oct 19, 7:46 pm, David Wang wrote:
>
>
>
>
>
> > On Oct 19, 2:48 am, JimLad wrote:
>
> > > On Oct 18, 4:02 pm, "Ken Schaefer"
> > > wrote:
>
> > > > I believe this is correct. The log entry is one of the last thing performed
> > > > for each request
>
> > > > Cheers
> > > > Ken
>
> > > > "JimLad" wrote in message
>
> > > >news:1192712226.033895.124230@y27g2000pre.googlegroups.com. ..
>
> > > > > Hi,
>
> > > > > In IIS 6.0 Log, does Time represent the end time or the start time?
> > > > > Doesn't matter much normally, but I have some time-out entries where
> > > > > time-taken is 6 minutes where it makes a huge difference.
>
> > > > > I think the time in the log is the end time, and that to get a rough
> > > > > approximation of the start time I need to subtract the time-taken. Am
> > > > > I correct?
>
> > > > > Cheers,
>
> > > > > James- Hide quoted text -
>
> > > > - Show quoted text -
>
> > > Thanks.
>
> > > Also just to clarify, when you get a new set of headers in the log,
> > > that indicates a website restart or an idle timeout on the worker
> > > process. Is that correct? Could anything else cause new headers to be
> > > written?
>
> > > Cheers,
>
> > > James- Hide quoted text -
>
> > > - Show quoted text -
>
> > You get a new set of headers whenever HTTP.SYS has to open the log
> > file to start writing a log entry to it.
>
> > What you have mentioned is a subset of possible actions that can cause
> > new headers to be written. There are others, but without a context, it
> > is not useful to list them.
>
> > //Davidhttp://w3-4u.blogspot.comhttp://blogs.msdn.com/David. Wang
> > //- Hide quoted text -
>
> > - Show quoted text -
>
> Well, I've been looking at a problem, which from the IIS log file
> looks like a db server problem (very slow or timeout on data access
> via SQLXML virtual directory, fine when just accessing files on web
> server). But there is a set of headers at about the same time. I
> suspect that this is a manual website restart in an attempt to solve
> the problem, but I'd like to be able to confirm that. As far as I am
> aware this isn't logged anywhere? There's nothing in the event log,
> although get the following about quarter of an hour later (but I think
> it's a red herring as the problem had resolved by then):
>
> Application popup: w3wp.exe - Application Error : The instruction at
> "0x4bc4ce39" referenced memory at "0x4bc4ce39". The memory could not
> be "read".- Hide quoted text -
>
> - Show quoted text -


A manual website restart can look like that in the log file.

By default, IIS only logs unexpected recycling of worker processes,
such as when it crashes. You can instruct IIS to log *all* (or
selected subset, based on bit-flags) recycling of worker processes.

This is special flag not exposed in the UI (in fact, the UI does not
expose ALL IIS functionality -- only the subset we think most people
will reasonably use. Thus, all the debugging features are not in the
UI). You set it on the Application Pool of interest, or globally
across all Application Pools.

LogEventOnRecycle

http://www.microsoft.com/technet/prodtechnol/WindowsServer20 03/Library/IIS/6f43da84-38b0-422b-aa2b-195643d05d22.mspx?mfr =true

CSCRIPT %SYSTEMDRIVE%\Inetpub\AdminScripts\ADSUTIL.VBS SET W3SVC/
AppPools/MyAppPool/LogEventOnRecycle 255

Your event log entry indicates SOMETHING in the worker process
crashed. I recommend following the following procedures to track it
down and get it resolved. Until you resolve crashes/hangs, strange
things like timeouts can always mysteriously happen.

http://blogs.msdn.com/david.wang/archive/2005/08/29/HOWTO_Un derstand_and_Diagnose_an_AppPool_Crash.aspx


//David
http://w3-4u.blogspot.com
http://blogs.msdn.com/David.Wang
//

Re: IIS Log Time column: Start or End Time?

am 22.10.2007 12:39:55 von JimLad

On Oct 22, 11:11 am, David Wang wrote:
> On Oct 22, 2:47 am, JimLad wrote:
>
>
>
>
>
> > On Oct 19, 7:46 pm, David Wang wrote:
>
> > > On Oct 19, 2:48 am, JimLad wrote:
>
> > > > On Oct 18, 4:02 pm, "Ken Schaefer"
> > > > wrote:
>
> > > > > I believe this is correct. The log entry is one of the last thing performed
> > > > > for each request
>
> > > > > Cheers
> > > > > Ken
>
> > > > > "JimLad" wrote in message
>
> > > > >news:1192712226.033895.124230@y27g2000pre.googlegroups.com. ..
>
> > > > > > Hi,
>
> > > > > > In IIS 6.0 Log, does Time represent the end time or the start time?
> > > > > > Doesn't matter much normally, but I have some time-out entries where
> > > > > > time-taken is 6 minutes where it makes a huge difference.
>
> > > > > > I think the time in the log is the end time, and that to get a rough
> > > > > > approximation of the start time I need to subtract the time-taken. Am
> > > > > > I correct?
>
> > > > > > Cheers,
>
> > > > > > James- Hide quoted text -
>
> > > > > - Show quoted text -
>
> > > > Thanks.
>
> > > > Also just to clarify, when you get a new set of headers in the log,
> > > > that indicates a website restart or an idle timeout on the worker
> > > > process. Is that correct? Could anything else cause new headers to be
> > > > written?
>
> > > > Cheers,
>
> > > > James- Hide quoted text -
>
> > > > - Show quoted text -
>
> > > You get a new set of headers whenever HTTP.SYS has to open the log
> > > file to start writing a log entry to it.
>
> > > What you have mentioned is a subset of possible actions that can cause
> > > new headers to be written. There are others, but without a context, it
> > > is not useful to list them.
>
> > > //Davidhttp://w3-4u.blogspot.comhttp://blogs.msdn.com/David. Wang
> > > //- Hide quoted text -
>
> > > - Show quoted text -
>
> > Well, I've been looking at a problem, which from the IIS log file
> > looks like a db server problem (very slow or timeout on data access
> > via SQLXML virtual directory, fine when just accessing files on web
> > server). But there is a set of headers at about the same time. I
> > suspect that this is a manual website restart in an attempt to solve
> > the problem, but I'd like to be able to confirm that. As far as I am
> > aware this isn't logged anywhere? There's nothing in the event log,
> > although get the following about quarter of an hour later (but I think
> > it's a red herring as the problem had resolved by then):
>
> > Application popup: w3wp.exe - Application Error : The instruction at
> > "0x4bc4ce39" referenced memory at "0x4bc4ce39". The memory could not
> > be "read".- Hide quoted text -
>
> > - Show quoted text -
>
> A manual website restart can look like that in the log file.
>
> By default, IIS only logs unexpected recycling of worker processes,
> such as when it crashes. You can instruct IIS to log *all* (or
> selected subset, based on bit-flags) recycling of worker processes.
>
> This is special flag not exposed in the UI (in fact, the UI does not
> expose ALL IIS functionality -- only the subset we think most people
> will reasonably use. Thus, all the debugging features are not in the
> UI). You set it on the Application Pool of interest, or globally
> across all Application Pools.
>
> LogEventOnRecycle
>
> http://www.microsoft.com/technet/prodtechnol/WindowsServer20 03/Librar...
>
> CSCRIPT %SYSTEMDRIVE%\Inetpub\AdminScripts\ADSUTIL.VBS SET W3SVC/
> AppPools/MyAppPool/LogEventOnRecycle 255
>
> Your event log entry indicates SOMETHING in the worker process
> crashed. I recommend following the following procedures to track it
> down and get it resolved. Until you resolve crashes/hangs, strange
> things like timeouts can always mysteriously happen.
>
> http://blogs.msdn.com/david.wang/archive/2005/08/29/HOWTO_Un derstand_...
>
> //Davidhttp://w3-4u.blogspot.comhttp://blogs.msdn.com/David. Wang
> //- Hide quoted text -
>
> - Show quoted text -

Thanks David. Very helpful.

Cheers,

James