[master] 00bb0b2e4 Add std.now() and std.timed_call()

[Nils Goroll]

commit 00bb0b2e4487400c47720c109de460543fa05193
Author: Nils Goroll <nils.goroll at uplex.de>
Date:   Tue Mar 16 15:14:57 2021 +0100

    Add std.now() and std.timed_call()
    
    std.now() fills a gap left by the stable time of the now variable in
    VCL: Sometimes we need to know the current time after some longer
    processing in VCL.
    
    std.timed_call() is intended to measure longer operations in
    VCL. std.timestamp() exists already to add accurate measurements to
    the log. std.timed_call() is for cases where the duration is required
    in VCL, for example to enrich HTTP requests/responses.

diff --git a/doc/sphinx/reference/vcl_var.rst b/doc/sphinx/reference/vcl_var.rst
index da3efa560..d97016976 100644
--- a/doc/sphinx/reference/vcl_var.rst
+++ b/doc/sphinx/reference/vcl_var.rst
@@ -1425,7 +1425,8 @@ now
 	in VCL, ``now`` will always represent the point in time when
 	the respective built-in VCL subroutine was entered. ``now`` is
 	thus not suitable for any kind of time measurements. See
-	:ref:`std.timestamp()` in :ref:`vmod_std(3)`.
+	:ref:`std.timestamp()`, :ref:`std.now()` and
+	:ref:`std.timed_call()` in :ref:`vmod_std(3)`.
 
 sess
 ~~~~
diff --git a/vmod/tests/std_b00001.vtc b/vmod/tests/std_b00001.vtc
index e0bc56023..6bba1c99f 100644
--- a/vmod/tests/std_b00001.vtc
+++ b/vmod/tests/std_b00001.vtc
@@ -1,4 +1,4 @@
-varnishtest "Test std.random()"
+varnishtest "Test std.random(), std.now(), std.timed_call()"
 
 server s1 {
 	rxreq
@@ -6,14 +6,22 @@ server s1 {
 } -start
 
 varnish v1 -vcl+backend {
+	import vtc;
 	import std;
 
-	sub vcl_deliver {
+	sub dice {
 		set resp.http.rnd1 = std.random(0, 1);
 		set resp.http.rnd2 = std.random(0, 10);
 		set resp.http.rnd3 = std.random(8, 10);
 		set resp.http.rnd4 = std.random(99, 100);
 	}
+
+	sub vcl_deliver {
+		set resp.http.t0 = std.integer(time=std.now());
+		vtc.sleep(1s);
+		set resp.http.rolling-us = std.timed_call(dice) * 1000 * 1000;
+		set resp.http.t1 = std.integer(time=std.now());
+	}
 } -start
 
 varnish v1 -cliok "debug.srandom"
@@ -25,4 +33,6 @@ client c1 {
 	expect resp.http.rnd2 == 0.390
 	expect resp.http.rnd3 == 8.585
 	expect resp.http.rnd4 == 99.636
+	expect resp.http.t1 -gt resp.http.t0
+	expect resp.http.rolling-us -gt 1
 } -run
diff --git a/vmod/vmod_std.c b/vmod/vmod_std.c
index 8ce144eb9..78a288d57 100644
--- a/vmod/vmod_std.c
+++ b/vmod/vmod_std.c
@@ -370,3 +370,22 @@ vmod_ban_error(VRT_CTX)
 		r = "";
 	return (r);
 }
+
+VCL_TIME v_matchproto_(td_std_now)
+vmod_now(VRT_CTX)
+{
+
+	(void) ctx;
+	return (VTIM_real());
+}
+
+VCL_DURATION v_matchproto_(td_std_timed_call)
+vmod_timed_call(VRT_CTX, VCL_SUB sub)
+{
+	vtim_mono b;
+
+	CHECK_OBJ_NOTNULL(ctx, VRT_CTX_MAGIC);
+	b = VTIM_mono();
+	VRT_call(ctx, sub);
+	return (VTIM_mono() - b);
+}
diff --git a/vmod/vmod_std.vcc b/vmod/vmod_std.vcc
index acd273c88..cef9590c4 100644
--- a/vmod/vmod_std.vcc
+++ b/vmod/vmod_std.vcc
@@ -659,6 +659,16 @@ Returns a textual error description of the last `std.ban()`_ call from
 the same task or the empty string if there either was no error or no
 `std.ban()`_ call.
 
+$Function TIME now()
+
+Returns the current time. In contrast to the ``now`` built-in
+variable, every call returns a new value.
+
+$Function DURATION timed_call(SUB)
+
+Call the given SUB and return a high precision measurement of the
+execution time.
+
 DEPRECATED functions
 ====================