`request` and `firstByte` phases inaccurately measured on NodeJS

[jgehrcke]

Coming from https://github.com/sindresorhus/got/issues/1080.

I went into the code a bit and did a quick experiment.

In my environment with NodeJS 12.16.1 we take this code path:

request.prependOnceListener('finish', onUpload);

https://github.com/szmarczak/http-timer/blob/c4783261a2926379eed6c4f58f8f18359c2f42c2/source/index.ts#L149

Notably, this uses the undocumented "finish" event on the http.ClientRequest object (see below*).

I sent an HTTP request with ~10 MB size, did a bit of network interface monitoring and manually compared the time the finished handler is invoked (when the onUpload() function is called), with the time it takes for the TCP stack of my operating system to actually flush out the data to the remote end.

I also know how the HTTP server in this case behaves: it creates a response immediately after having received the complete request body, w/o looking at the body.

Actual timings:

request (time it took for sending out the request over TCP): ~24 seconds first response byte (time it took until response arrived after the request was sent out): ~0 seconds

Measured timings

request: ~7 seconds first response byte: ~17 seconds

Conclusions

In the discussed example the mid-request timing information as returned by http-timer is completely off (start to end is measured correctly, but the inner phases are not at all).

What seems to happen is that when sending a request with a non-empty body then all timings relying on the request phase measurement show skewed data.

More specifically, depending on the size of the HTTP request body the timing measurements can become pretty terribly incorrect/misleading.

The "time to the first response byte" is often used for measuring server performance, and as shown above it can be wildly overestimated.

Most probably this is because the "user land code" has absolutely no clue when the last byte of the request body actually left the TCP stack. Probably this is because of a big buffer between the operating system's TCP stack and the actual code. Might have to do with https://nodejs.org/api/stream.html#stream_buffering.

Probably the "finished" event on the request fires once the data has been written to that big buffer (managed by the NodeJS runtime), and from there the data is potentially quite slowly flushed out via TCP.

Not sure what we can do; I do not have a lot of experience with NodeJS. But I noticed in the documentation that request.end() might provide the right tool via the callback that you can pass to it. It's documented with:

If callback is specified, it will be called when the request stream is finished.

I don't know what "when the request stream is finished" really means, though.

Maybe this library should come with a big disclaimer that it is known that it might produce utterly wrong numbers for the "mid phases" of the request/response cycle when the request contains a non-empty body. What do you think?

*: Undocumented here: https://nodejs.org/docs/latest-v12.x/api/http.html# and here: https://nodejs.org/docs/latest-v13.x/api/http.html -- the "finish" event is only documented on these pages for the http.ServerResponse class. Interesting enough. No documentation means no guarantee. When is the "finished" event meant to be emitted? In comparison to that: when is it actually emitted? These are important questions.

[szmarczak]

Notably, this uses the undocumented "finish" event

Either you forgot that the ClientRequest is a Writable stream or simply didn't know that.

[szmarczak]

Maybe this library should come with a big disclaimer that it is known that it might produce utterly wrong numbers for the "mid phases" of the request/response cycle when the request contains a non-empty body

Please do research first before judging.