Measuring the total time of serving a request

[Mitar]

Hi!

I would like to measure the total time of serving a request. From what
I was looking around, generally one could do that with a middleware
handler, which starts measuring time, calls ServeHTTP of the original
handler, and once ServeHTTP returns, measures the time it took.

But I am not completely convinced that this really takes into the
account full total time of serving a request (besides time spent
inside stdlib to pass the request to my code): ServeHTTP can call
Write which buffers data to be send and return, but I would like to
also take into the account total time it took to send this data out
(at least out of the program into the kernel). Am I right that this
time might not be captured with the approach above? Is there a way to
also measure the time it takes for buffers to be written out?

I am considering calling Flush in the middleware, before measuring the
end time. My understanding is that it would block until data is
written out. But I am not sure if that would have some other
unintended side effects?

Maybe measuring that extra time is not important in practice? I am
thinking of trying to measure it because it might be that the client's
connection is slow (maybe by malice) and would like to have some data
on how often that is happening.


Mitar

--
https://mitar.tnode.com/
https://twitter.com/mitar_m
https://noc.social/@mitar

[Duncan Harris]

I would argue that it doesn't matter.

The buffers in the operating system can often substantially exceed the size of those in the Go runtime.

Try using an artificially slow reader (e.g. curl --limit-rate) and you should see.

Why do you care about buffering in Go vs the OS?

[Mitar]

Hi!

On Mon, Nov 20, 2023 at 10:26 AM Duncan Harris <dun...@harris3.org> wrote:
> Why do you care about buffering in Go vs the OS?

Just because I hope that in Go I might have a chance to know when they
are written out than in OS.

[Uli Kunitz]

You could convert the original ResponseWriter to a ResponseController and call Flush in your middleware before you measure the duration. Alternatively you can try to convert ResponseWriter to a http.Flusher and call Flush if the conversion is successful.

The documentation says "Flush flushes buffered data to the client." Note that if proxies are used, this will push the data only to the proxy. In today's proxies-everywhere-world, the next Proxy might be a sidecar container in of the pod of your application. You will measure only how fast the kernel can transfer a skbuff value from one socket to another and process the netfilter rules in between.

[Mitar]

Hi!

On Mon, Nov 20, 2023 at 10:51 PM Uli Kunitz <uli.k...@gmail.com> wrote:
> You could convert the original ResponseWriter to a ResponseController and call Flush in your middleware before you measure the duration. Alternatively you can try to convert ResponseWriter to a http.Flusher and call Flush if the conversion is successful.

Yes, I was thinking something along those lines. But are there any
side effects by calling Flush after the main handler returns? Like in
Write documentation it says:

"if the total size of all written data is under a few KB and there are
no Flush calls, the Content-Length header is added automatically."

"Once the headers have been flushed (...), the request body may be unavailable."

My understanding is that after the main handler returns, none of this
matters anymore. But are there any other similar side effects?

[Ulrich Kunitz]

You are right Flush needs to write the header first, so the additional header lines cannot be added by the server after Flush. The automatic Content-Type might also not be written. A local proxy in front of your server might be a simpler approach to measure full performance.

If the actual processing time of the request is not sufficient for you, you might want to use a proxy in front of the server to measure performance.