[master] 064f034 Add std.timestamp() method

[Martin Blix Grydeland]

commit 064f03498b6d9f11156a1f5ab0648b992495a08b
Author: Martin Blix Grydeland <martin at varnish-software.com>
Date:   Wed Mar 26 13:22:01 2014 +0100

    Add std.timestamp() method

diff --git a/bin/varnishtest/tests/m00013.vtc b/bin/varnishtest/tests/m00013.vtc
new file mode 100644
index 0000000..c3a6295
--- /dev/null
+++ b/bin/varnishtest/tests/m00013.vtc
@@ -0,0 +1,44 @@
+varnishtest "Timestamps from std vmod"
+
+server s1 {
+	rxreq
+	txresp
+} -start
+
+varnish v1 -vcl+backend {
+	import ${vmod_std};
+
+	sub vcl_init {
+		# Make sure that this doesn't cause ill effects
+		std.timestamp("bogus");
+	}
+
+	sub vcl_recv {
+		std.timestamp("vcl_recv");
+	}
+
+	sub vcl_backend_fetch {
+		std.timestamp("vcl_backend_fetch");
+	}
+} -start
+
+logexpect l1 -v v1 -g request {
+	expect 0 1001	Begin		req
+	expect * =	Timestamp	Start:
+	expect * =	Timestamp	{vcl_recv: \S+ 0\.\d+ 0\.\d+}
+	expect * =	Timestamp	Resp:
+	expect * =	End
+	expect 0 1002	Begin		bereq
+	expect * =	Timestamp	Start:
+	expect * =	Timestamp	{vcl_backend_fetch: \S+ 0\.\d+ 0\.\d+}
+	expect * =	Timestamp	BerespBody:
+	expect * =	End
+} -start
+
+client c1 {
+	txreq
+	rxresp
+	expect resp.status == 200
+} -run
+
+logexpect l1 -wait
diff --git a/lib/libvmod_std/vmod.vcc b/lib/libvmod_std/vmod.vcc
index dcb12ec..b1b7010 100644
--- a/lib/libvmod_std/vmod.vcc
+++ b/lib/libvmod_std/vmod.vcc
@@ -145,6 +145,15 @@ $Function INT port(IP)
 Description
 	Returns the port number of an IP address.
 
+$Function VOID timestamp(STRING)
+
+Description
+	Introduces a timestamp in the log with the current time. Uses
+	the argument as the timespamp label. This is useful to time
+	the execution of lengthy VCL procedures, and makes the
+	timestamps inserted automatically by Varnish more accurate.
+Example
+	std.timestamp("curl-request");
 
 SEE ALSO
 ========
diff --git a/lib/libvmod_std/vmod_std.c b/lib/libvmod_std/vmod_std.c
index 7301559..233c2da 100644
--- a/lib/libvmod_std/vmod_std.c
+++ b/lib/libvmod_std/vmod_std.c
@@ -41,6 +41,7 @@
 #include "vrt.h"
 #include "vtcp.h"
 #include "vsa.h"
+#include "vtim.h"
 
 #include "cache/cache.h"
 #include "cache/cache_backend.h"
@@ -204,3 +205,23 @@ vmod_port(const struct vrt_ctx *ctx, VCL_IP ip)
 		return (0);
 	return (VSA_Port(ip));
 }
+
+VCL_VOID __match_proto__(td_std_timestamp)
+vmod_timestamp(const struct vrt_ctx *ctx, VCL_STRING label)
+{
+
+	CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
+	if (label == NULL)
+		return;
+	if (*label == '\0')
+		return;
+	if (ctx->bo != NULL && ctx->req == NULL) {
+		/* Called from backend vcl methods */
+		CHECK_OBJ_NOTNULL(ctx->bo, BUSYOBJ_MAGIC);
+		VSLb_ts_busyobj(ctx->bo, label, VTIM_real());
+	} else if (ctx->req != NULL) {
+		/* Called from request vcl methdos */
+		CHECK_OBJ_NOTNULL(ctx->req, REQ_MAGIC);
+		VSLb_ts_req(ctx->req, label, VTIM_real());
+	}
+}