proxy: log time now relative to resp lifetime

Originally I envisioned taking an inbound request object, tagging it
with the time, and at the very end of a function logging is called. This
would give you the total time of the "backend" part of a request.

On rethinking, the timing information that's most useful in the proxy's
perspective is the time it takes for a response to happen + the status
of a response. One request may generate several sub-responses and it is
impossible to check the timing of each of those and log outliers.

You now cannot get the total time elapsed in a function anymore, but I
believe that is less useful information to the user of a proxy. The best
picture of latency will still be from the client, and response latency
can educate the proxy on issues with backends.

resp:elapsed() has been added as a compromise; it returns the elapsed
microseconds that a response took, so you can add the time together and
get an approximation of total time (if running req/resp's sequentially).

This change also means that calling mcp.await() and waiting for multiple
responses will give the timing of each sub-response accurately.

1 files changed, 10 insertions, 8 deletions

diff --git a/proxy_lua.c b/proxy_lua.c
index 7fa07bb..bb70ad7 100644
--- a/proxy_lua.c
+++ b/proxy_lua.c
@@ -7,6 +7,12 @@
 // normal library open:
 // int luaopen_mcp(lua_State *L) { }
 
+static int mcplib_response_elapsed(lua_State *L) {
+    mcp_resp_t *r = luaL_checkudata(L, -1, "mcp.response");
+    lua_pushinteger(L, r->elapsed);
+    return 1;
+}
+
 // resp:ok()
 static int mcplib_response_ok(lua_State *L) {
     mcp_resp_t *r = luaL_checkudata(L, -1, "mcp.response");
@@ -811,6 +817,7 @@ static int mcplib_log_req(lua_State *L) {
     int rtype = 0;
     int rcode = 0;
     int rstatus = 0;
+    long elapsed = 0;
     char *rname = NULL;
     char *rport = NULL;
 
@@ -823,14 +830,11 @@ static int mcplib_log_req(lua_State *L) {
         rstatus = rs->status;
         rname = rs->be_name;
         rport = rs->be_port;
+        elapsed = rs->elapsed;
     }
     size_t dlen = 0;
     const char *detail = luaL_optlstring(L, 3, NULL, &dlen);
 
-    struct timeval end;
-    gettimeofday(&end, NULL);
-    long elapsed = (end.tv_sec - rq->start.tv_sec) * 1000000 + (end.tv_usec - rq->start.tv_usec);
-
     logger_log(l, LOGGER_PROXY_REQ, NULL, rq->pr.request, rq->pr.reqlen, elapsed, rtype, rcode, rstatus, detail, dlen, rname, rport);
 
     return 0;
@@ -871,6 +875,7 @@ static int mcplib_log_reqsample(lua_State *L) {
     int rtype = 0;
     int rcode = 0;
     int rstatus = 0;
+    long elapsed = 0;
     char *rname = NULL;
     char *rport = NULL;
 
@@ -886,14 +891,11 @@ static int mcplib_log_reqsample(lua_State *L) {
         rstatus = rs->status;
         rname = rs->be_name;
         rport = rs->be_port;
+        elapsed = rs->elapsed;
     }
     size_t dlen = 0;
     const char *detail = luaL_optlstring(L, 6, NULL, &dlen);
 
-    struct timeval end;
-    gettimeofday(&end, NULL);
-    long elapsed = (end.tv_sec - rq->start.tv_sec) * 1000000 + (end.tv_usec - rq->start.tv_usec);
-
     bool do_log = false;
     if (allerr && rstatus != MCMC_OK) {
         do_log = true;