Repository metrics
- Stars
- (27,997 stars)
- PR merge metrics
- (Avg merge 8d) (378 merged PRs in 30d)
Description
Description:
As previously discussed with @dio in Slack: we would like to access timing information for the current request and response from the Lua filter. This information is not currently available via the Lua API, but it does exist in C++ as stored in the StreamInfo class.
I have written a simple patch that exposes the information, but its use in practice is not straightforward: when called from the envoy_on_request Lua callback (e.g. handle:streamInfo():timings()), the vast majority of the timings are missing, because the Lua filter runs very early in the request lifecycle. In fact, we only have access to the timing for the first received byte for the request.
Even worse: when called from the Lua envoy_on_response callback, there are no timings available either: since the response callback also runs very early, and the actual timings for all the events in the response are set on the StreamInfo all at once, at the very end, by calling setUpstreamTiming, we have a strange situation where we're in a response handler and we've already started parsing the response from the upstream (we definitely have access to all the headers), but we don't have access to e.g. how long it took the upstream to send back the first byte of the response.
Right now I'm working around the issue by calling handle:trailers() from envoy_on_response. In both HTTP/1 and HTTP/2, this method yields the Lua context long enough for Envoy to finish processing the request and setting all the relevant timings. This is not ideal because it significantly increases the time spent in the Lua handler just to be able to access timing information that should be readily available as soon as the handler is called (e.g. the time when the first response byte was received).
I would like to discuss possible ways to work around the issue. One of the options I've discussed with @dio is not exporting all the timings from streamInfo and instead exposing a monotonic clock that can be called from Lua, allowing the user to measure whatever intervals they require. Another option would be changing setUpstreamTiming to be incremental, so the timings are available in Lua as soon as they're available in C++, but this is not trivial because as stated in the comments, setUpstreamTiming is also used in cases where there are several upstream requests in flight and only one can win... But how does this even interact with the Lua filter anyway? Is the Lua envoy_on_response callback called once for each request in flight?
Thanks for your help with this!