1514369 - Collect timing data for requests that were served from the cache

Status: NEW

(Core :: Networking: Cache, enhancement, P3)

Description

[Markus Stange [:mstange]]

Example profile: https://perfht.ml/2LhTYIp

For network requests that are served by the network, the corresponding profiler markers contain timestamps for requestStart, responseStart, and responseEnd. These timestamps let us draw differently-colored bars in the network panel of the profiler UI.
And the time between responseEnd and the marker's endTime gives us information about how long the OnStopRequest runnable was waiting in the main thread's event queue.

However, for requests that were served from the cache, we do not get any more detailed timestamps. The profiler only sees the timestamps that were captured in the main thread; these timestamps get stored as startTime and endTime in the marker JSON.

Here are two sets of example JSON, obtained using the marker table's "Copy marker JSON" context menu item.

Request that was served by the network:
> {
>   "start": 62509.049764203126,
>   "dur": 132.9439199999979,
>   "name": "Load 294: https://m.media-amazon.com/images/S/abs-image-upload-na/7/ams/ATVPDKIKX0DER/f959f248cbce8d64515863957a85a411.w400.h400._CR0,0,400,400_AC_SX200_SY200_.png",
>   "data": {
>     "status": "STATUS_STOP",
>     "count": 6974,
>     "pri": 10,
>     "URI": "https://m.media-amazon.com/images/S/abs-image-upload-na/7/ams/ATVPDKIKX0DER/f959f248cbce8d64515863957a85a411.w400.h400._CR0,0,400,400_AC_SX200_SY200_.png",
>     "startTime": 62509.049764203126,
>     "requestStart": 62540.678843203124,
>     "responseStart": 62595.16473120313,
>     "responseEnd": 62595.756582203125,
>     "endTime": 62641.993684203124,
>     "type": "Network",
>     "id": 7413113553190
>   },
>   "title": null
> }


Request that was (presumably) served by the cache:
> {
>   "start": 47916.9496433125,
>   "dur": 29.096498999999312,
>   "name": "Load 150: https://images-na.ssl-images-amazon.com/images/I/01ZxBiK0vuL.css?AUIClients/SXWidgetAssets",
>   "data": {
>     "status": "STATUS_STOP",
>     "pri": 0,
>     "URI": "https://images-na.ssl-images-amazon.com/images/I/01ZxBiK0vuL.css?AUIClients/SXWidgetAssets",
>     "startTime": 47916.9496433125,
>     "endTime": 47946.0461423125,
>     "type": "Network",
>     "id": 16505559318678
>   },
>   "title": null
> }

The former has startTime, requestStart, responseStart, responseEnd, endTime.
The latter only has startTime and endTime.

It would be great to get some more insight into the different phases of cache lookup:
 - How much time do we spend sitting in some kind of queue?
 - How much time do we spend waiting for the disk?
 - At what point does some thread have the bytes that we need?

Most importantly, I'd like to have enough information so that we can separate the time during which we're blocked from the time during which actual useful work is happening. At the moment, the UI fills markers without requestStart/responseStart/responseEnd info with a solid color, which makes it look like the entire time is spent doing useful work, but I think that's mostly inaccurate.