feat: extract server timings and measure individual retrievals

[kylehuntsman]

Pulls the Server-Timing response header logic into it's own file and updates the retrieval event parsing to get timing on individual retrieval attempts. This tracks the individual events that occur on a per retrieval basis, whereas before we were treating "retrieval" as a phase and tracking all events under that phase. This was problematic since the second event of any type, for example during a second concurrent retrieval, would overwrite any previous event and it's timings.

The following is an example of the Server-Timing response header when fetching bafybeic56z3yccnla3cutmvqsn5zy3g24muupcsjtoyp3pu5pm5amurjx4/birb.mp4 via the daemon. I've added newlines for each comma delimited item.

Server-Timing: 
started-finding-candidates;dur=0.1301;candidates-found=179140830;candidates-filtered=179186930,
retrieval-Bitswap;dur=179.38963,
retrieval-12D3KooWKGCcFVSAUXxe7YP62wiwsBvpCmMomnNauJCA67XbmHYj;dur=179.36533,
retrieval-12D3KooWPgBdZSbmKbD7ZQGjU7gZCcCKGvWSnBf1q4xAbpDdtJaJ;dur=179.44633;connected-to-sp=5900;first-byte-received=404370468;failed-retrieval=404419368,
retrieval-12D3KooWJ8YAF6DiRxrzcxoeUVjSANYxyxU55ruFgNvQB4EHibpG;dur=179.43173,
retrieval-QmUA9D3H7HeCYsirB3KmPSvZh3dNXMZas6Lwgr4fv1HTTp;dur=179.48633;connected-to-sp=151700;first-byte-received=498249083,
retrieval-12D3KooWDCXxiSsLi1NT9tsiyimwV6YstQkrjTjD2hAkz2KRVAGG;dur=179.49513;connected-to-sp=181700

Explaination

Due to the caveat explained below, all the "dur" fields are actually the time since the started-fetch event, while the individual metric extras are the duration since the beginning of that metric in nanoseconds.

Caveats

We are unable to get the duration of the entire fetch/successful retrievals due to the way in which the headers are written. Since the headers are written before an http Write occurs, we can only collect info about the retrievals until a first-byte-received event that results in data being written to the client. The http Write ends up occurring before the success and finished events are emitted, therefore cutting off the trailing events that occur for any given retrieval. Because of this, the started-fetch, success, and finished events are not processed.

[codecov-commenter]

Codecov Report

Merging #332 (05ec3c4) into feat/discreet-events (81a2850) will decrease coverage by 0.39%.
The diff coverage is 100.00%.

Additional details and impacted files

@@                   Coverage Diff                    @@
##           feat/discreet-events     #332      +/-   ##
========================================================
- Coverage                 76.40%   76.02%   -0.39%     
========================================================
  Files                        84       85       +1     
  Lines                      6361     6318      -43     
========================================================
- Hits                       4860     4803      -57     
- Misses                     1230     1244      +14     
  Partials                    271      271              

Impacted Files	Coverage Δ
pkg/retriever/bitswapretriever.go	93.42% <100.00%> (ø)
pkg/server/http/ipfs.go	65.96% <100.00%> (-3.52%)	⬇️
pkg/server/http/servertimingssubscriber.go	100.00% <100.00%> (ø)

... and 10 files with indirect coverage changes

[willscott]

for the started on each of the retrievals, i would have that set as the dur for the line - having the first number named that way makes it render in standard browser tooling.