Add %D to log complete request time (beginning to end) in varnishncsa. Patches against varnish master & 3.0.3.

varnishncsa-request-time-vs-master.patch

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.

varnishncsa-request-time.patch

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 : "-");

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

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.