proposal: net/http, net/http/httptrace: add mechanism for tracing request serving

[CAFxX]

For the purpose of accurate request tracing when serving HTTP requests (for both HTTP/1.x and HTTP/2), it would be ideal if http.Handlers could obtain a time.Time representing the time of first byte of the request.

In this context, time of first byte would be the best estimate of the instant when the go process reads the first byte of the HTTP request line from the socket (i.e. ignoring the time spent in hardware queues and in kernel buffers).

Between the time of first byte and the time the first http.Handler is invoked for that request quite some time can pass since in that interval all headers must be received (and parsed) and the request body must start. If the client is slow then this interval can be extremely long.

Furthermore, when using the middleware pattern for tracing, the order of middleware can influence the recorded time at which the request starts to be handled. This can skew metrics and the accuracy of tracing, leading to hard-to-debug performance issues.

With this proposal implemented, all of the above issues would be solved:

• request parsing would be correctly accounted for
• slow clients can be correctly accounted for
• request start time can be reliably detected irrespective of middleware order

This information could be included either in the http.Request struct, returned by a method on http.Request, or attached to the request context.Context (perhaps via something like the httptrace.ServerTrace suggestion below by @odeke-em).

---

update: rephrased according to @odeke-em's suggestions

[odeke-em]

Thank you for filing this issue @CAFxX!

So in regards to Transports and HTTP clients, have you perhaps encountered httptrace.ClientTrace https://golang.org/pkg/net/http/httptrace/#ClientTrace

It provides hooks for a bunch of events like:
a) WroteRequest
b) WroteHeaders
c) GotFirstResponseByte

Direction

You talk about

In this context, time of first byte would be the best estimate of the time at which the go process reads the first byte of the HTTP request line (i.e. ignoring the time spent in hardware queues and the socket buffers).
...
Between the first byte to when the first http.Handler is invoked quite some time can pass, since in that interval all headers must be received (and parsed) and the request body must start. If the client is slow then this interval can be extremely long.
...
This information could be included either in the http.Request struct, returned by a method on http.Request, or attached to the context.Context.

It seems to me that this issue is a feature request for http.Server to attach timing information for processing of requests? If so, let’s modify the title and the wording to make this clear and that’ll perhaps aid in proposal review.

Proposal

Building off your suggestions and comments, perhaps:
This issue perhaps could be solved if net/http/httptrace had:
a) func ContextServerTrace(context.Context) *ServerTrace
b) A net/http/httptrace.ServerTrace struct

type ServerTrace struct {
       TimeToFirstRequestByte time.Duration
       BufferSize int64
       TimeToFirstHeader time.Duration
       ...
}

If perhaps this suits the requirements, we can make the issue title “proposal: net/http, net/http/httptrace: add mechanism for tracing request serving”

[seankhliao]

Earlier httptrace ServerTrace proposal #18997

[CAFxX]

@odeke-em yes, your interpretation is absolutely correct (sorry, I jotted it down in a haste, and clarity was definitely lacking). I changed the title and tried to clarify things a bit.

I also incorporated a pointer to your suggested interface. I just have a couple of question about it though:

• what would the semantics of the time.Duration in this case? What would be the start and end instants of these two durations? Put otherwise: how can I obtain a time.Time representing the instant in time when the corresponding events occurred?
• what's the BufferSize for?

[odeke-em]

what would the semantics of the time.Duration in this case? What would be the start and end instants of these two durations? Put otherwise: how can I obtain a time.Time representing the instant in time when the corresponding events occurred?

Great question, so I was thinking that each timing would be an event offset from an origin time aka time the request was first received. We could have the origin time e.g. ReceivedRequestAt time.Time or RequestStartTime time.Time, instead of having both ReceivedRequestAt time.Time and TimeToFirstRequestByte time.Time. Offsets from a single origin time keep the data in the form of an event log and reduce unnecessary computations needed by users to detail the story of the request.

what's the BufferSize for?

BufferSize is meant to capture how much data was needed to be buffered before a full response could be read and the handler was initiated, for example it could be the length of the initial data stream for HTTP/2.

Earlier httptrace ServerTrace proposal #18997

Thank you @seankhliao for finding that ServerTrace proposal. @CAFxX the proposal that @seankhliao referred to has been open for a while and has even more discussion and context. Perhaps let's close this one and transfer the discussion there?

[CAFxX]

@CAFxX the proposal that @seankhliao referred to has been open for a while and has even more discussion and context. Perhaps let's close this one and transfer the discussion there?

After going through #18997 I am not sure about whether that's sensible: the proposal scope in #18997 is significantly wider, and as a result the design proposed there has run into problems (circular dependencies between net/http and net/http/httputil) that seemingly caused that proposal to get hopelessly stuck and see no significant activity for the last 2.5 years.

Most likely this proposal could be implemented on the framework of #18997, but as that proposal seem to be not going anywhere due to scope, I don't think increasing the scope further will be of benefit to either of them.

Note that this proposal does not necessarily require the specific solution of #18997 (httputil.ServerTrace): there are other pragmatic solutions mentioned above.

So, if possible, I'd vote to keep the two proposals separate. I can definitely mention the use case in #18997, but merging seems unnecessary.

[gopherbot]

Change https://golang.org/cl/227438 mentions this issue: net/http: prototype ServerTraceState to capture state of a request being handled

[odeke-em]

Gotcha, thank you! I couldn't sleep so I instead prototyped something with CL https://go-review.googlesource.com/c/go/+/227438, please take a look. From the ideas I was able to spin up, we'll have code such as:

Code

func main() {
        cst := httptest.NewTLSServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
                ts := r.ServerTraceState()
                fmt.Printf("Request was received at: %s.\n", ts.ReceivedAt)
                fmt.Printf("Header processing started after: %s.\nFinished after: %s.\nTotal time to parse headers: %s.\n\n",
                        ts.ParsedHdrsStartAt.Sub(ts.ReceivedAt),
                        ts.ParsedHdrsEndAt.Sub(ts.ReceivedAt),
                        ts.ParsedHdrsEndAt.Sub(ts.ParsedHdrsStartAt))
                fmt.Printf("TLS handshaking started after: %s.\nTime for TLS handshake: %s\n\n",
                        ts.TLSHandshakeStartAt.Sub(ts.ReceivedAt),
                        ts.TLSHandshakeEndAt.Sub(ts.TLSHandshakeStartAt))
                fmt.Printf("Reading the first byte started after: %s.\nTime to read first byte: %s.\n\n",
                        ts.FirstByteStartAt.Sub(ts.ReceivedAt),
                        ts.FirstByteEndAt.Sub(ts.FirstByteStartAt))
                fmt.Printf("Composing the request before passing it into this handler took: %s.\n",
                        ts.ParsedRequestAt.Sub(ts.ReceivedAt))
        }))
        defer cst.Close()

        req, _ := http.NewRequest("GET", cst.URL, nil)
        res, err := cst.Client().Do(req)
        if err != nil {
                panic(err)
        }
        _, _ = ioutil.ReadAll(res.Body)
        _ = res.Body.Close()
}

Output

Request was received at: 2020-04-07 03:20:46.320637 -0700 PDT m=+0.001848575.
Header processing started after: 1.331644ms.
Finished after: 1.337667ms.
Total time to parse headers: 6.023µs.

TLS handshaking started after: 14.448µs.
Time for TLS handshake: 1.274575ms

Reading the first byte started after: 1.310963ms.
Time to read first byte: 13.904µs.

Composing the request before passing it into this handler took: 1.344004ms.

It is meant to show how this can be done and as a starting point to further the proposal and discussions.

[CAFxX]

Functionally (w.r.t. the problem described in this issue) LGTM. This is quite more than I would expect from an MVP. :D

While I'm not sure whether we need all that granularity right away, looking at a full-blown prototype like this is very useful though:

1. I don't have strong feelings about whether this should be always-on/opt-in/opt-out, even though maybe opt-out would be best (rationale: good functional default that allows users that don't care about tracing to not pay the extra cost).
2. As a future extension, since IIRC the request body can be read asynchronously in the background, it may make sense to have also the timestamp of when the last byte of the request body is received (absolutely out of scope for now, also because it would require synchronization with the handler)
3. This is not a particularly strong argument for instants instead of durations, but anyway: instants have a better zero value to signify "this event did not happen", e.g. TLS handshake for non-TLS connections (while unlikely, a duration of 0 could mean both that the event did not happen, or that it happened very quickly)
4. Given points (2) and (3), maybe it would be more forward-looking to provide "getters" instead of exposing the timestamps/durations directly? (this would allow e.g. to safely implement synchronization) -- update: ah maybe this is not required since ServerTraceState() is already getter-like

[odeke-em]

Thank you for the feedback, and for taking a look, @CAFxX!

In response to your points:

1. A setting on http.Server before creation perhaps, but also they are just timers so not sure about the overhead except via allocations
2. The last byte of the request is impractical because these is telemetry that will be available right before, and within the handler i.e. request bodies can still be streaming until the very last byte is read, and at that point this mechanism will be out of scope
3. Right, so that's what I deduced too as I was thinking of a design. Another problem with durations is that when you try to calculate offsets since each other e.g. when TLS handshaking finished, you have to add ts.ReceivedAt.Add(ts.TLSHandshakeStartAt + ts.TLSHandshakeEndAt)
4. I had initially thought about making it an interface which is why you'll traceState and ServerTraceState but really given that it'll be available for use in a handler and won't be modified anymore, the use of getters just unnecessarily complicates it