Skip to content

Instantly share code, notes, and snippets.

Embed
What would you like to do?
Add %D to log complete request time (beginning to end) in varnishncsa. Patches against varnish master & 3.0.3.
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.
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 : "-");
@JonathanHuot

This comment has been minimized.

Copy link

@JonathanHuot JonathanHuot commented Jan 31, 2013

Dontt you think it would be better to write only on sscanf instead of calling twice ? :-) It will be more phkish

@KlausBrunner

This comment has been minimized.

Copy link
Owner Author

@KlausBrunner KlausBrunner commented Jan 31, 2013

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.

@linuxsupport

This comment has been minimized.

Copy link

@linuxsupport linuxsupport commented Feb 24, 2013

"time from beginning to completion of request" is this in millisecond or microsecond?

@tfheen

This comment has been minimized.

Copy link

@tfheen tfheen commented Mar 13, 2013

Please make it just use sscanf once, provide a patch against master and update the docs and I'll be happy to merge this.

@KlausBrunner

This comment has been minimized.

Copy link
Owner Author

@KlausBrunner KlausBrunner commented Apr 16, 2013

@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.

@KlausBrunner

This comment has been minimized.

Copy link
Owner Author

@KlausBrunner KlausBrunner commented Apr 29, 2013

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