apache access logs out of chronological order. Why?

[httpwebwitch]

Usually when I look at the access logs, the timestamps are all in chronological order.

I'm troubleshooting a problem in my app that happens daily, each morning at around 8:15am, so I'm looking at the logs for around that time. I notice that the times aren't sequential. eg:

1.1.1.1 - - [18/Oct/2010:08:16:14 -0400] "GET ..."
1.1.1.1 - - [18/Oct/2010:08:15:14 -0400] "GET ..."
1.1.1.1 - - [18/Oct/2010:08:15:14 -0400] "GET ..."
1.1.1.1 - - [18/Oct/2010:08:15:14 -0400] "GET ..."
1.1.1.1 - - [18/Oct/2010:08:15:14 -0400] "GET ..."
1.1.1.1 - - [18/Oct/2010:08:15:14 -0400] "GET ..."
1.1.1.1 - - [18/Oct/2010:08:16:15 -0400] "GET ..."
1.1.1.1 - - [18/Oct/2010:08:16:15 -0400] "GET ..."
1.1.1.1 - - [18/Oct/2010:08:16:15 -0400] "GET ..."
1.1.1.1 - - [18/Oct/2010:08:15:15 -0400] "GET ..."
1.1.1.1 - - [18/Oct/2010:08:15:15 -0400] "GET ..."

(IP and request changed/omitted for privacy)


See how there are some entries that are timestamped a minute out of sync from those around them?

These are just a few examples - the same asyncronicity is happening fairly often in the logs.

What would cause that?

If the timestamp is a record of when the request was completed and the response sent, then how could they get out of order in the logs? Not just by a second, but by an entire minute? And if the timestamp is recording some other step in the HTTP process, then what does this mean?

[g1smd]

It could be that the clock in the server is unstable, and some internal process corrects and updates the date and time periodically.

[sublime1]

Another possible reason is that the log entry is written after the request completes, but the in-memory part of the log is created at the moment of the request. Thus, log records are chronological by time of initial request, but timestamped with the time of the request completion.

If someone disconnects in the middle of a request, or has a really slow connection, or for a couple of other reasons, you can get this kind of thing.

It's possible to create a custom log format in Apache that adds a few bits of information that can be really useful, notably the duration of the request (either in seconds, or nanoseconds ... but oddly not milliseconds -- go figure :-). Check out the CustomLog directive and various flags you can use to tack on additional information to the end of your logs.

Tom