diff options
author | dormando <dormando@rydia.net> | 2023-01-05 18:36:22 -0800 |
---|---|---|
committer | dormando <dormando@rydia.net> | 2023-01-05 18:36:22 -0800 |
commit | db855da755f297df3165809073b0ca6a6299fcbd (patch) | |
tree | d080622f12962848c361fc7ffefb51a86f622db8 /proxy_await.c | |
parent | 3158e85e84909c81eeb60e719c3d582677ec32c8 (diff) | |
download | memcached-db855da755f297df3165809073b0ca6a6299fcbd.tar.gz |
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.
Diffstat (limited to 'proxy_await.c')
-rw-r--r-- | proxy_await.c | 7 |
1 files changed, 7 insertions, 0 deletions
diff --git a/proxy_await.c b/proxy_await.c index 4a548a3..33e4cd3 100644 --- a/proxy_await.c +++ b/proxy_await.c @@ -101,6 +101,7 @@ static void mcp_queue_await_io(conn *c, lua_State *Lc, mcp_request_t *rq, int aw // reserve one uservalue for a lua-supplied response. mcp_resp_t *r = lua_newuserdatauv(Lc, sizeof(mcp_resp_t), 1); memset(r, 0, sizeof(mcp_resp_t)); + 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 @@ -385,7 +386,13 @@ int mcplib_await_return(io_pending_proxy_t *p) { } // lose our internal mcpres reference regardless. + // also tag the elapsed time into the response. if (p->mcpres_ref) { + struct timeval end; + 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); + luaL_unref(L, LUA_REGISTRYINDEX, p->mcpres_ref); } // our await_ref is shared, so we don't need to release it. |