DO NOT REPLY [Bug 21500] - access logs are not 100% sorted by time

[bu...@apache.org]

DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG 
RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT
<http://nagoya.apache.org/bugzilla/show_bug.cgi?id=21500>.
ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND 
INSERTED IN THE BUG DATABASE.

http://nagoya.apache.org/bugzilla/show_bug.cgi?id=21500

access logs are not 100% sorted by time

trawick@apache.org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|                            |WONTFIX



------- Additional Comments From trawick@apache.org  2003-07-12 11:08 -------
It is too expensive to have access log entries sorted strictly by time when
written by Apache.  All entries written by any thread in the whole server would
have to be channelled through one single thread that kept them sorted.  There
are a couple of reasons for this:

1) request time is not calculated right at the time of logging, so other delays
in the processing of that request could hold it up and allow later requests to
be logged first
2) even if the request time is calculated right at the time of logging, the
thread just about to call the kernel to append the entry to the file could lose
the CPU to another thread which generates its later timestamp and successfully
appends to the file

Here is some code from mod_log_config.c you can tweak to reduce but not
eliminate out-of-order entries, at the cost of slowing down the server a bit. 
You can stick "#define I_INSIST_ON_EXTRA_CYCLES_FOR_CLF_COMPLIANCE"  at the top
of mod_log_config.c and recompile to enable the code that grabs the time closer
to the time of writing to the file.

static const char *log_request_time(request_rec *r, char *a)
{
    apr_time_exp_t xt;

    /* ###  I think getting the time again at the end of the request
     * just for logging is dumb.  i know it's "required" for CLF.
     * folks writing log parsing tools don't realise that out of order
     * times have always been possible (consider what happens if one
     * process calculates the time to log, but then there's a context
     * switch before it writes and before that process is run again the
     * log rotation occurs) and they should just fix their tools rather
     * than force the server to pay extra cpu cycles.  if you've got
     * a problem with this, you can set the define.  -djg
     */
    if (a && *a) {              /* Custom format */
        /* The custom time formatting uses a very large temp buffer
         * on the stack.  To avoid using so much stack space in the
         * common case where we're not using a custom format, the code
         * for the custom format in a separate function.  (That's why
         * log_request_time_custom is not inlined right here.)
         */
#ifdef I_INSIST_ON_EXTRA_CYCLES_FOR_CLF_COMPLIANCE
        ap_explode_recent_localtime(&xt, apr_time_now());
#else
        ap_explode_recent_localtime(&xt, r->request_time);
#endif
        return log_request_time_custom(r, a, &xt);
    }

A custom piped logger might be the best way to deal with this.  It can hold onto
entries for some time (up to 10 secs in your case) to catch out of order
entries, then write them out sorted.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org