Page MenuHomeFreeBSD

Time to First byte in and out
Needs ReviewPublic

Authored by rrs on Mon, May 18, 7:59 PM.

Details

Reviewers
tuexen
Group Reviewers
transport
Summary

An important statistic in determining if a server process (or client) is being delayed
is to know the time to first byte in and time to first byte out. Currently we
have no way to know these all we have is t_starttime. That (t_starttime) tells us
what time the 3 way handshake completed. We don't know when the first
request came in or how quickly we responded. Nor from a client perspective
do we know how long from when we sent out the first byte before the
server responded.

This small change adds the ability to track the TTFB's. This will show up in
BB logging which then can be pulled for later analysis.

Test Plan

Create a simple server that turns on BB logging and accepts a connection
gets a request and responds. It should do several request responses so we
can make sure that we see only the TTFB in and out once. We can examine
the BB logs to find this information.

Diff Detail

Lint
Lint Skipped
Unit
Unit Tests Skipped

Event Timeline

rrs requested review of this revision.Mon, May 18, 7:59 PM
rrs created this revision.

Just a quick question - do you really need both (t_fbyte_in and t_fbyte_out) variables in TCPCB in full?

Wouldn't it suffice to first (before TF2_FBYTES_COMPLETE is set) only store the start timestamp (there is a provision to make it non-zero under all circumstances), and by the end-time, immediately subtract that from the current timestamp (ticks) to only store the delta (which, I believe, is the main deliverable here; or do you want to observe the relative t_fbyte_in / t_fbyte_out among a set of flows, to see if the application was particularly slow for certain overlapping requests (or when too many requests to the application became outstanding, etc?)

If you have both, and since you made provisions that neither can ever be zero, when assigned, the TF2_FBYTES_COMPLETE is a redundant flag...

rrs added a comment.Wed, May 20, 11:22 AM

Richard:

I don't think that holding just the delta is what you really want. You want to be able
to tell when the first byte came in and the first byte went out. The delta only gives
one a partial view of what happened. And we are not living in 1984 where 64k of
memory is a lot. Four bytes to get more detailed information is I think worth it.

In D24902#548693, @rrs wrote:

Richard:

I don't think that holding just the delta is what you really want. You want to be able
to tell when the first byte came in and the first byte went out.

Right, but that is not clear from the description of this diff - do you want to know the time relative to wall clock on human timescales, or just the delta in machine timescale (where e.g. milliseconds are a lot).

Unless I'm mistaken, ticks runs at the rate of Hz (typically millisecond resolution) correct? So, while a 32 bit counter will only overrun once per ~1,5 months, I now wonder if the resolution is fine enough for the intended purpose. At least in my world, we try to track our IOs with a granularity of around 0.1 to 1 usec (which is no longer sufficient for NVMe stuff)...

And you could potentially have both - first use a uint64 with the absolte start time (at usec resolution), and then calculate a usec-res delta until the first byte out, and a msec-res "wall-clock" related start time, and store both as two uint32 in the same space...

The delta only gives one a partial view of what happened. And
we are not living in 1984

Oh, we are living in a future that is in many aspects so way beyond 1984, it's frightening :)

where 64k of memory is a lot. Four bytes to get more detailed information is I think worth it.

Right, but L1 / L2 / L3 cache is still a precious and contended resource IMHO.

rrs added a comment.Mon, May 25, 11:39 AM

Has discussed on the transport call, I will be updating these to have a uint64_t and a nano-second basis for the values (including t_starttime I think since this
is what you compare these against) :)

rstone added a subscriber: rstone.Mon, May 25, 2:45 PM
In D24902#550400, @rrs wrote:

Has discussed on the transport call, I will be updating these to have a uint64_t and a nano-second basis for the values (including t_starttime I think since this
is what you compare these against) :)

Wouldn't sbintime_t be easier and cheaper to work with?