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 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 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 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 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 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 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
You can’t perform that action at this time.