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 : "-"); |
I find the code slightly more maintainable (and the patch a little less intrusive) the way it is now, but I'm okay with anything that improves the chances of including this feature in Varnish.
"time from beginning to completion of request" is this in millisecond or microsecond?
Please make it just use sscanf once, provide a patch against master and update the docs and I'll be happy to merge this.
@linuxsupport: Time in seconds, as everything logged by varnishncsa.
@tfheen There's now a patch against master with just a single sscanf as the first file, and the old patch is kept for reference.
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.
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Dontt you think it would be better to write only on sscanf instead of calling twice ? :-) It will be more phkish