View | Details | Raw Unified | Return to bug 54363
Collapse All | Expand All

(-)modules/loggers/mod_log_config.c.orig (-35 / +121 lines)
Lines 97-105 Link Here
97
 * %...r:  first line of request
97
 * %...r:  first line of request
98
 * %...s:  status.  For requests that got internally redirected, this
98
 * %...s:  status.  For requests that got internally redirected, this
99
 *         is status of the *original* request --- %...>s for the last.
99
 *         is status of the *original* request --- %...>s for the last.
100
 * %...t:  time, in common log format time format
100
 * %...t:  time, in common log format time format, in localtime.
101
 * %...{format}t:  The time, in the form given by format, which should
101
 * %...{format}t:  The time, in the form given by format, which should
102
 *                 be in strftime(3) format.
102
 *                 be in strftime(3) format, in localtime.
103
 * %...g:  time, in common log format time format, in GMT.
104
 * %...{format}g:  The time, in the form given by format, which should
105
 *                 be in strftime(3) format, in GMT.
103
 * %...T:  the time taken to serve the request, in seconds.
106
 * %...T:  the time taken to serve the request, in seconds.
104
 * %...D:  the time taken to serve the request, in micro seconds.
107
 * %...D:  the time taken to serve the request, in micro seconds.
105
 * %...u:  remote user (from auth; may be bogus if return status (%s) is 401)
108
 * %...u:  remote user (from auth; may be bogus if return status (%s) is 401)
Lines 148-153 Link Here
148
#include "apr_hash.h"
151
#include "apr_hash.h"
149
#include "apr_optional.h"
152
#include "apr_optional.h"
150
#include "apr_anylock.h"
153
#include "apr_anylock.h"
154
#include "apr_atomic.h"
151
155
152
#define APR_WANT_STRFUNC
156
#define APR_WANT_STRFUNC
153
#include "apr_want.h"
157
#include "apr_want.h"
Lines 569-584 Link Here
569
                                           apr_time_exp_t *xt)
573
                                           apr_time_exp_t *xt)
570
{
574
{
571
    apr_size_t retcode;
575
    apr_size_t retcode;
572
    char tstr[MAX_STRING_LEN];
576
#define MAX_TIME_LEN 128
573
    apr_strftime(tstr, &retcode, sizeof(tstr), a, xt);
577
    char * const tstr = apr_palloc(r->pool, MAX_TIME_LEN);
574
    return apr_pstrdup(r->pool, tstr);
578
    apr_strftime(tstr, &retcode, MAX_TIME_LEN, a, xt);
579
    return retcode ? tstr : NULL;
580
    /* Don't return empty string, return NULL instead so caller can 
581
     * replace with "-".
582
     */
575
}
583
}
576
584
577
#define DEFAULT_REQUEST_TIME_SIZE 32
578
typedef struct {
585
typedef struct {
579
    unsigned t;
586
    char str[32];
580
    char timestr[DEFAULT_REQUEST_TIME_SIZE];
587
} timestr_t;
581
    unsigned t_validate;
588
/* We define it as a struct so that we can use a C89 copy-of-struct,
589
 * because we cannot use memcpy for memory marked volatile */
590
typedef struct {
591
    timestr_t timestr; /* First for alignment of copies */
592
    apr_uint32_t key;
582
} cached_request_time;
593
} cached_request_time;
583
594
584
#define TIME_FMT_CUSTOM          0
595
#define TIME_FMT_CUSTOM          0
Lines 589-597 Link Here
589
#define TIME_FMT_ABS_MSEC_FRAC   5
600
#define TIME_FMT_ABS_MSEC_FRAC   5
590
#define TIME_FMT_ABS_USEC_FRAC   6
601
#define TIME_FMT_ABS_USEC_FRAC   6
591
602
592
#define TIME_CACHE_SIZE 4
603
#define TIME_CACHE_SIZE ((AP_TIME_RECENT_THRESHOLD) + 1)
593
#define TIME_CACHE_MASK 3
604
#define TIME_CACHE_MASK (AP_TIME_RECENT_THRESHOLD)
594
static cached_request_time request_time_cache[TIME_CACHE_SIZE];
605
static cached_request_time request_time_cache_lt[TIME_CACHE_SIZE];
606
static cached_request_time request_time_cache_gmt[TIME_CACHE_SIZE];
595
607
596
static apr_time_t get_request_end_time(request_rec *r)
608
static apr_time_t get_request_end_time(request_rec *r)
597
{
609
{
Lines 604-610 Link Here
604
}
616
}
605
617
606
618
607
static const char *log_request_time(request_rec *r, char *a)
619
static const char *log_request_time(request_rec *r, char *a,
620
    cached_request_time *cache,
621
    apr_status_t (*explode)(apr_time_exp_t *, apr_time_t))
608
{
622
{
609
    apr_time_exp_t xt;
623
    apr_time_exp_t xt;
610
    apr_time_t request_time = r->request_time;
624
    apr_time_t request_time = r->request_time;
Lines 695-723 Link Here
695
         * for the custom format in a separate function.  (That's why
709
         * for the custom format in a separate function.  (That's why
696
         * log_request_time_custom is not inlined right here.)
710
         * log_request_time_custom is not inlined right here.)
697
         */
711
         */
698
        ap_explode_recent_localtime(&xt, request_time);
712
        explode(&xt, request_time);
699
        return log_request_time_custom(r, a, &xt);
713
        return log_request_time_custom(r, a, &xt);
700
    }
714
    }
701
    else {                                   /* CLF format */
715
    else {                                   /* CLF format */
702
        /* This code uses the same technique as ap_explode_recent_localtime():
716
        /* This code uses the same technique as cached_explode
703
         * optimistic caching with logic to detect and correct race conditions.
717
         * from server/util_time.c.
704
         * See the comments in server/util_time.c for more information.
705
         */
718
         */
706
        cached_request_time* cached_time = apr_palloc(r->pool,
719
        timestr_t * const timestr_p = apr_palloc(r->pool, sizeof(timestr_t));
707
                                                      sizeof(*cached_time));
720
        /* Above allocates memory from the request pool to return the 
708
        unsigned t_seconds = (unsigned)apr_time_sec(request_time);
721
         * time string result in. */
709
        unsigned i = t_seconds & TIME_CACHE_MASK;
722
#define SECONDS_MASK 0x7FFFFFFF
710
        *cached_time = request_time_cache[i];
723
        /* High bit is used to indicate invalid cache_element */
711
        if ((t_seconds != cached_time->t) ||
724
        const apr_uint32_t seconds = apr_time_sec(request_time) & SECONDS_MASK;
712
            (t_seconds != cached_time->t_validate)) {
725
        volatile cached_request_time * const cache_element =
713
726
            &(cache[seconds & TIME_CACHE_MASK]);
714
            /* Invalid or old snapshot, so compute the proper time string
727
        /* The cache is implemented as a ring buffer.  Each second,
715
             * and store it in the cache
728
         * it uses a different element in the buffer.  The timestamp
716
             */
729
         * in the element indicates whether the element contains the
730
         * time string for the current second (vs the time
731
         * 'now - AP_TIME_RECENT_THRESHOLD' seconds ago).  If the
732
         * cached value is for the current time, we copy the time string.
733
         * After copying, we check the cache_element to see if it still has the 
734
         * same second. If so, the copy is valid, because we always set the key 
735
         * after copying the time string into the cache, and we're using 
736
         * memory barriers (implemented with Compare-And-Swap) 
737
         * that guarantee total memory ordering.
738
         */
739
        const apr_uint32_t key = cache_element->key; 
740
        /* Above is done speculatively, no memory barrier used.
741
         * It's doing the same thing as apr_atomic_read32, a read of
742
         * memory marked volatile, but without doing the function call. */
743
        if (seconds == key && seconds != 0) {
744
            /* seconds==0 may mean cache is uninitialized, so don't use cache */
745
            *timestr_p = cache_element->timestr;
746
            /* After copying time string, make sure cache_element 
747
             * was not marked invalid by another thread beginning an update, 
748
             * and that cache_element really contained data for our second.
749
             * Requires memory barrier, so use CAS. */
750
            if (apr_atomic_cas32(&cache_element->key, seconds, seconds)
751
                == seconds) 
752
            {
753
                return timestr_p->str;
754
            }
755
        }
756
        /* Invalid cache element, so calculate the time string value.
757
           This is a wait-free algorithm, and we purposely don't spin and
758
           retry to get from the cache, we just continue and calculate it
759
           and do useful work, instead of spinning. */
760
        do {
717
            char sign;
761
            char sign;
718
            int timz;
762
            int timz;
719
763
720
            ap_explode_recent_localtime(&xt, request_time);
764
            explode(&xt, request_time);
721
            timz = xt.tm_gmtoff;
765
            timz = xt.tm_gmtoff;
722
            if (timz < 0) {
766
            if (timz < 0) {
723
                timz = -timz;
767
                timz = -timz;
Lines 726-744 Link Here
726
            else {
770
            else {
727
                sign = '+';
771
                sign = '+';
728
            }
772
            }
729
            cached_time->t = t_seconds;
773
            apr_snprintf(timestr_p->str, sizeof(timestr_p->str),
730
            apr_snprintf(cached_time->timestr, DEFAULT_REQUEST_TIME_SIZE,
731
                         "[%02d/%s/%d:%02d:%02d:%02d %c%.2d%.2d]",
774
                         "[%02d/%s/%d:%02d:%02d:%02d %c%.2d%.2d]",
732
                         xt.tm_mday, apr_month_snames[xt.tm_mon],
775
                         xt.tm_mday, apr_month_snames[xt.tm_mon],
733
                         xt.tm_year+1900, xt.tm_hour, xt.tm_min, xt.tm_sec,
776
                         xt.tm_year+1900, xt.tm_hour, xt.tm_min, xt.tm_sec,
734
                         sign, timz / (60*60), (timz % (60*60)) / 60);
777
                         sign, timz / (60*60), (timz % (60*60)) / 60);
735
            cached_time->t_validate = t_seconds;
778
        } while (0);
736
            request_time_cache[i] = *cached_time;
779
780
        /* Attempt to update the cache */
781
        
782
        /* To prevent ABA problem, don't update the cache unless we have a
783
         * newer time value (so that we never go from B->A). 
784
         * Handle cases where seconds overflows (e.g. year 2038), 
785
         * and cases where cache is uninitialized.
786
         * Handle overflow, otherwise it will stop caching after overflow,
787
         * until server process is restarted, which may be months later.
788
         */
789
#define OVERFLOW (((SECONDS_MASK)>>1) + 1)
790
        if (key <= SECONDS_MASK /* another thread not updating cache_element */
791
            && seconds != 0 /* new key distinguishable from uninitialized */
792
            && (
793
            (seconds > key && seconds - key < OVERFLOW) || /* normal */
794
            (seconds < key && key - seconds > OVERFLOW) || /* overflow */
795
            (key == 0 && seconds < SECONDS_MASK - 0x100)))
796
            /* cache is perhaps uninitialized, and not recent overflow */
797
        {
798
            if (key == apr_atomic_cas32(&cache_element->key, ~seconds, key))
799
            {   /* We won the race to update this cache_element.
800
                 * Above marks cache_element as invalid by using ~seconds, 
801
                 * because we are starting an update: it's the start of a
802
                 * transaction. */
803
                cache_element->timestr = *timestr_p;
804
                /* Finished copying, now update key with our key,
805
                 * ending the transaction. Need to use CAS for the
806
                 * memory barrier. 
807
                 */
808
               apr_atomic_cas32(&cache_element->key, seconds, ~seconds);
809
            }
737
        }
810
        }
738
        return cached_time->timestr;
811
        return timestr_p->str;
739
    }
812
    }
740
}
813
}
741
814
815
static const char *log_request_time_lt(request_rec *r, char *a)
816
{
817
    return log_request_time(r, a, 
818
        request_time_cache_lt, &ap_explode_recent_localtime);
819
}
820
821
static const char *log_request_time_gmt(request_rec *r, char *a)
822
{
823
    return log_request_time(r, a, 
824
        request_time_cache_gmt, &ap_explode_recent_gmt);
825
}
826
742
static const char *log_request_duration(request_rec *r, char *a)
827
static const char *log_request_duration(request_rec *r, char *a)
743
{
828
{
744
    apr_time_t duration = get_request_end_time(r) - r->request_time;
829
    apr_time_t duration = get_request_end_time(r) - r->request_time;
Lines 1646-1652 Link Here
1646
        log_pfn_register(p, "A", log_local_address, 0 );
1731
        log_pfn_register(p, "A", log_local_address, 0 );
1647
        log_pfn_register(p, "l", log_remote_logname, 0);
1732
        log_pfn_register(p, "l", log_remote_logname, 0);
1648
        log_pfn_register(p, "u", log_remote_user, 0);
1733
        log_pfn_register(p, "u", log_remote_user, 0);
1649
        log_pfn_register(p, "t", log_request_time, 0);
1734
        log_pfn_register(p, "t", log_request_time_lt, 0);
1735
        log_pfn_register(p, "g", log_request_time_gmt, 0);
1650
        log_pfn_register(p, "f", log_request_file, 0);
1736
        log_pfn_register(p, "f", log_request_file, 0);
1651
        log_pfn_register(p, "b", clf_log_bytes_sent, 0);
1737
        log_pfn_register(p, "b", clf_log_bytes_sent, 0);
1652
        log_pfn_register(p, "B", log_bytes_sent, 0);
1738
        log_pfn_register(p, "B", log_bytes_sent, 0);

Return to bug 54363