HTTP Filter - NewRelic Request Queueing (X-Request-Start header)

[jippi]

Title: Add support for the X-Request-Start header

Description:
This header allow NewRelic (and other similar services) to measure routing latency as part of the request duration, rather than just the time taken to process the request in the HTTP handler

It basically only require a header named X-Request-Start with the value of "${msec}" which is specced as time in seconds with a milliseconds resolution at the time of the log write - which mean when nginx sent the request upstream

Relevant Links:

NewRelic documentation

[mattklein123]

@jippi I'm sorry I don't understand what time the header is supposed to track. Can you describe in more detail? I looked at the linked documentation but it did not clear it up for me. Does it track the time in milliseconds between when the request is fully received and when the request starts being proxied to upstream?

[mattklein123]

cc @PiotrSikora if you know off the top of your head what the nginx header variable ^ actually means.

[PiotrSikora]

$msec is UNIX time with milliseconds precision after a dot, i.e. 1509409603.723.

[jippi]

@mattklein123 the value should be when envoy starts sending the request to a cluster backend, so when the request leaves envoy and goes to the network for an application backend server.

The NewRelic APM tool will then read this value when the application SDK runs (e.g. PHP start to serve the request) and compare it to the current time, thus having a time difference for how long the request waited in network/nginx/apache queue in the system.

It will look like below in newrelic, and is a great help to figure out if a request was slow due to network, webserver or the application code itself.

[mattklein123]

OK easy enough. Marking help wanted.

[jippi]

@mattklein123 whats the "currency" to bribe my way to getting this feature into envoy? :)

[mattklein123]

@jippi I would find someone to work on it. :) A few quick comments:

1. I'm pretty sure you could trivially do this using Lua if you need to get something working quickly.
2. If we universally set x-request-start in the router filter it's a trivial change, though for perf reasons I'm not sure we universally want to set it.
3. So if we don't universally set it we can add an option to the router filter to set the header potentially.

[jippi]

Hi @mattklein123

I've been playing with this again in envoy during a company hackathon

It seem trivial to do in lua, except that there are no out-of-the-box way to get time with millisecond resolution - especially inside the confined sandbox which envoy runs lua scripts.

Would the above make it more likely to be included as a http filter baked into envoy? :) or maybe a way to expose the time in ms to lua somehow ?

[mattklein123]

Would the above make it more likely to be included as a http filter baked into envoy?

I would probably just add an option to the router filter to set the header.

maybe a way to expose the time in ms to lua somehow

Also very easy change to add a Lua API to get high resolution time.

[jippi]

@mattklein123 any chance of getting one or the other into 1.7 before the release is cut? :)

[dio]

@jippi I think if we want to make it configurable, could you suggest the configuration here? I'm not sure if we want a configurable header's key name as well (but I think that is probably preferable), in that case, we should provide the header key name somehow, e.g.

track_start_time: { header: "x-request-start", resolution: "ms" }

(this is just an idea, not sure about the correctness of the config keys etc)

IMO, this "start time" could be captured:

1. In UpstreamRequest constructor or,
2. To be equal with: downstream_request_complete_time_.

WDYT?

[jippi]

I think the key can be static, in my (limited) experience, all tools use x-request-start to track it, since NewRelic added it first, and everyone else just copied it - similar the value is always ms resolution. Linkerd implemented it with a static key/value - and just a http filter

The header (imo) should be injected when envoy gets the inbound request, so latency include envoy processing as well as networking time