From db855da755f297df3165809073b0ca6a6299fcbd Mon Sep 17 00:00:00 2001 From: dormando Date: Thu, 5 Jan 2023 18:36:22 -0800 Subject: 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. --- proto_proxy.c | 7 +++++++ 1 file changed, 7 insertions(+) (limited to 'proto_proxy.c') 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 -- cgit v1.2.1