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, 7 insertions, 0 deletions

diff --git a/proto_proxy.c b/proto_proxy.c
index 5a40c7d..eb6f5e6 100644
--- a/proto_proxy.c
+++ b/proto_proxy.c
@@ -300,8 +300,14 @@ void proxy_return_cb(io_pending_t *pending) {
     if (p->is_await) {
         mcplib_await_return(p);
     } else {
+        struct timeval end;
         lua_State *Lc = p->coro;
 
+        // stamp the elapsed time into the response object.
+        gettimeofday(&end, NULL);
+        p->client_resp->elapsed = (end.tv_sec - p->client_resp->start.tv_sec) * 1000000 +
+            (end.tv_usec - p->client_resp->start.tv_usec);
+
         // in order to resume we need to remove the objects that were
         // originally returned
         // what's currently on the top of the stack is what we want to keep.
@@ -840,6 +846,7 @@ static void mcp_queue_io(conn *c, mc_resp *resp, int coro_ref, lua_State *Lc) {
     memset(r, 0, sizeof(mcp_resp_t));
     r->buf = NULL;
     r->blen = 0;
+    gettimeofday(&r->start, NULL);
     // Set noreply mode.
     // TODO (v2): the response "inherits" the request's noreply mode, which isn't
     // strictly correct; we should inherit based on the request that spawned