Last active
October 13, 2015 09:37
-
-
Save klausbrunner/4175582 to your computer and use it in GitHub Desktop.
Add %D to log complete request time (beginning to end) in varnishncsa. Patches against varnish master & 3.0.3.
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
diff --git a/bin/varnishncsa/varnishncsa.c b/bin/varnishncsa/varnishncsa.c | |
index 0b039b6..10664c7 100644 | |
--- a/bin/varnishncsa/varnishncsa.c | |
+++ b/bin/varnishncsa/varnishncsa.c | |
@@ -39,6 +39,7 @@ | |
* %l Client user ID as reported by identd (always "-") | |
* %u User ID if using HTTP authentication, or "-" | |
* %t Date and time of request | |
+ * %D time from beginning to completion of request | |
* %r Request line | |
* %s Status code | |
* %b Length of reply body, or "-" | |
@@ -100,6 +101,7 @@ static struct logline { | |
struct tm df_t; /* %t, Date and time */ | |
char *df_u; /* %u, Remote user */ | |
char *df_ttfb; /* Time to first byte */ | |
+ char *df_tt; /* %D, time taken to serve request */ | |
const char *df_hitmiss; /* Whether this is a hit or miss */ | |
const char *df_handling; /* How the request was handled | |
(hit/miss/pass/pipe) */ | |
@@ -253,6 +255,7 @@ clean_logline(struct logline *lp) | |
freez(lp->df_s); | |
freez(lp->df_u); | |
freez(lp->df_ttfb); | |
+ freez(lp->df_tt); | |
VTAILQ_FOREACH_SAFE(h, &lp->req_headers, list, h2) { | |
VTAILQ_REMOVE(&lp->req_headers, h, list); | |
freez(h->key); | |
@@ -556,19 +559,26 @@ collect_client(struct logline *lp, enum VSL_tag_e tag, unsigned spec, | |
case SLT_ReqEnd: | |
{ | |
- char ttfb[64]; | |
+ char ttfb[64], tt[64]; | |
+ double begint, endt; | |
if (!lp->active) | |
break; | |
if (lp->df_ttfb != NULL || | |
- sscanf(ptr, "%*u %*u.%*u %ld.%*u %*u.%*u %s", &l, ttfb) | |
- != 2) { | |
+ sscanf(ptr, "%lf %lf %*u.%*u %s", &endt, &begint, ttfb) | |
+ != 3) { | |
clean_logline(lp); | |
break; | |
} | |
+ | |
+ sprintf(tt, "%.9f", endt - begint); | |
+ if (lp->df_tt != NULL) | |
+ free(lp->df_tt); | |
+ lp->df_tt = strdup(tt); | |
+ | |
if (lp->df_ttfb != NULL) | |
free(lp->df_ttfb); | |
lp->df_ttfb = strdup(ttfb); | |
- t = l; | |
+ t = (long)endt; | |
localtime_r(&t, &lp->df_t); | |
/* got it all */ | |
lp->complete = 1; | |
@@ -724,6 +734,10 @@ h_ncsa(void *priv, enum VSL_tag_e tag, unsigned fd, | |
VSB_cat(os, tbuf); | |
break; | |
+ case 'D': | |
+ VSB_cat(os, lp->df_tt); | |
+ break; | |
+ | |
case 'U': | |
VSB_cat(os, lp->df_U ? lp->df_U : "-"); | |
break; | |
diff --git a/doc/sphinx/reference/varnishncsa.rst b/doc/sphinx/reference/varnishncsa.rst | |
index 2937b26..050f16f 100644 | |
--- a/doc/sphinx/reference/varnishncsa.rst | |
+++ b/doc/sphinx/reference/varnishncsa.rst | |
@@ -55,6 +55,9 @@ The following options are available: | |
In CLF format, i.e. a '-' rather than a 0 when no | |
bytes are sent. | |
+ %D | |
+ Entire time taken to serve request, in seconds. | |
+ | |
%H | |
The request protocol. Defaults to HTTP/1.0 if not | |
known. |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
diff --git a/bin/varnishncsa/varnishncsa.c b/bin/varnishncsa/varnishncsa.c | |
index ff07ed5..24af723 100644 | |
--- a/bin/varnishncsa/varnishncsa.c | |
+++ b/bin/varnishncsa/varnishncsa.c | |
@@ -39,6 +39,7 @@ | |
* %l Client user ID as reported by identd (always "-") | |
* %u User ID if using HTTP authentication, or "-" | |
* %t Date and time of request | |
+ * %D time from beginning to completion of request | |
* %r Request line | |
* %s Status code | |
* %b Length of reply body, or "-" | |
@@ -98,6 +99,7 @@ static struct logline { | |
struct tm df_t; /* %t, Date and time */ | |
char *df_u; /* %u, Remote user */ | |
char *df_ttfb; /* Time to first byte */ | |
+ char *df_tt; /* %D, time taken to serve request */ | |
const char *df_hitmiss; /* Whether this is a hit or miss */ | |
const char *df_handling; /* How the request was handled (hit/miss/pass/pipe) */ | |
int active; /* Is log line in an active trans */ | |
@@ -244,6 +246,7 @@ clean_logline(struct logline *lp) | |
freez(lp->df_s); | |
freez(lp->df_u); | |
freez(lp->df_ttfb); | |
+ freez(lp->df_tt); | |
VTAILQ_FOREACH_SAFE(h, &lp->req_headers, list, h2) { | |
VTAILQ_REMOVE(&lp->req_headers, h, list); | |
freez(h->key); | |
@@ -550,6 +553,18 @@ collect_client(struct logline *lp, enum VSL_tag_e tag, unsigned spec, | |
clean_logline(lp); | |
break; | |
} | |
+ | |
+ double begint, endt; | |
+ if(sscanf(ptr, "%*u %lf %lf %*u.%*u %*s", &begint, &endt) == 2) { | |
+ char tt[64]; | |
+ sprintf(tt, "%.9f", endt - begint); | |
+ if (lp->df_tt != NULL) | |
+ free(lp->df_tt); | |
+ lp->df_tt = strdup(tt); | |
+ } | |
+ | |
+ if (lp->df_ttfb != NULL) | |
+ free(lp->df_ttfb); | |
lp->df_ttfb = strdup(ttfb); | |
t = l; | |
localtime_r(&t, &lp->df_t); | |
@@ -698,6 +713,10 @@ h_ncsa(void *priv, enum VSL_tag_e tag, unsigned fd, | |
strftime(tbuf, sizeof tbuf, "[%d/%b/%Y:%T %z]", &lp->df_t); | |
VSB_cat(os, tbuf); | |
break; | |
+ | |
+ case 'D': | |
+ VSB_cat(os, lp->df_tt); | |
+ break; | |
case 'U': | |
VSB_cat(os, lp->df_U ? lp->df_U : "-"); |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
It appears that there's now a similar patch in Varnish trunk (varnish/Varnish-Cache@9e6b75d), so this here should no longer be needed for future releases.