ChromeDriver - Network Performance Logging: Understanding timing section of Network.responseReceived

[Rajalingam Ramasamy]

Hi All,

I am trying to understand the relationship between the attributes in the timing section of network performance log message. I need this to measure the performance of application automatically. I am running ChromeDriver with Network Performance Logging. I am pulling out the log messages (Selenium - Java). Below is sample log messages and my understanding so far.

My Goals: Measure the following aspects of the site.

1. Queuing (time taken by browser since the time it knows that request have to be issued till it issues the request)
2. Establishing Connection (time taken by browser to establish the connection inclusive of dns, proxy, connnect and ssl)
3. Sending (time taken to send the request)
4. TTFB (time taken by server to send the response back - actual server processing time)
5. Downloading (time taken by browser to download the content)        

A) For each request I see following type of network calls: requestWillBeSent, responseReceived and loadingFinished. I assume that

• requestWillBeSent is logged when browser knows that the call have to be issued
• responseReceived is logged when the browser actually issues the request and start getting the response
• loadingFinished is logged when the browser completes loading

  Please confirm if the above understanding is right.
 
B) Each of those log messages have a timestamp. Can they be trusted for measuring performance?

C) I believe responseReceived.params.response.timing.XXXStart and XXXEnd are in ms. The difference between them indicates the time taken to perform that operation. Please confirm.

D) From which point these timings (timing.XXXStart) are measured? Is it from responseReceived.params.response.timing.requestTime?

E) What does timing.receiveHeadersEnd indicates? Is it the total time taken from responseReceived.params.response.timing.requestTime till completion of request?

F) I believe these factors helps in measuring time slices 2, 3 and 4 above. Is it possible to measure 1 and 5?

I tried other forums as well and finally landed here. Any pointers on this will be great.

Thanks Much, Raja

{
    "method": "Network.requestWillBeSent",
    "params": {
        "documentURL": "http://myserver.mydomain.com/",
        "frameId": "908.1",
        "initiator": {
            "lineNumber": 224,
            "type": "parser",
            "url": "http://myserver.mydomain.com/"
        },
        "loaderId": "908.1",
        "request": {
            "headers": {
                "Referer": "http://myserver.mydomain.com/",
                "User-Agent": "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.143 Safari/537.36"
            },
            "initialPriority": "High",
            "method": "GET",
            "mixedContentType": "none",
            "url": "http://myserver.mydomain.com/mypath"
        },
        "requestId": "908.6",
        "timestamp": 159745.02379,
        "type": "Other",
        "wallTime": 1475253246.05578
    }
}
{
    "method": "Network.responseReceived",
    "params": {
        "frameId": "908.1",
        "loaderId": "908.1",
        "requestId": "908.6",
        "response": {
            "connectionId": 32,
            "connectionReused": false,
            "encodedDataLength": -1,
            "fromDiskCache": false,
            "fromServiceWorker": false,
            "headers": {...},
            "headersText": "...",
            "mimeType": "application/javascript",
            "protocol": "http/1.1",
            "remoteIPAddress": "XX.XX.XX.XX",
            "remotePort": 8080,
            "requestHeaders": {...},
            "requestHeadersText": "...",
            "securityState": "neutral",
            "status": 200,
            "statusText": "OK",
            "timing": {
                "connectEnd": 40.8400000014808,
                "connectStart": 3.85999999707565,
                "dnsEnd": 3.85999999707565,
                "dnsStart": 3.85999999707565,
                "proxyEnd": 3.85999999707565,
                "proxyStart": 2.53899997915141,
                "pushEnd": 0,
                "pushStart": 0,
                "receiveHeadersEnd": 381.741999997757,
                "requestTime": 159745.025128,
                "sendEnd": 41.2369999976363,
                "sendStart": 40.9849999996368,
                "sslEnd": -1,
                "sslStart": -1,
                "workerReady": -1,
                "workerStart": -1
            },
            "url": "http://myserver.mydomain.com/mypath"
        },
        "timestamp": 159745.408348,
        "type": "Script"
    }
},
{
    "method": "Network.loadingFinished",
    "params": {
        "encodedDataLength": 15714,
        "requestId": "908.6",
        "timestamp": 159746.201989
    }
}

[Blaise Bruer]

see: https://chromedevtools.github.io/debugger-protocol-viewer/tot/Network/

Timing is usually captured early on in the cpp code, so it should be fairly reliable.

You may be interested in using the PerformanceTiming API: https://developer.mozilla.org/en-US/docs/Web/API/PerformanceTiming

--
You received this message because you are subscribed to the Google Groups "Google Chrome Developer Tools" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-chrome-develo...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/google-chrome-developer-tools/0b46383d-d349-4b26-90f1-632371f2613d%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Paul Irish]

A few more things I can add..

On Sat, Oct 1, 2016 at 5:44 PM, Rajalingam Ramasamy <rajalinga...@gmail.com> wrote:

Hi All,

I am trying to understand the relationship between the attributes in the timing section of network performance log message. I need this to measure the performance of application automatically. I am running ChromeDriver with Network Performance Logging. I am pulling out the log messages (Selenium - Java). Below is sample log messages and my understanding so far.

My Goals: Measure the following aspects of the site.

1. Queuing (time taken by browser since the time it knows that request have to be issued till it issues the request)
2. Establishing Connection (time taken by browser to establish the connection inclusive of dns, proxy, connnect and ssl)
3. Sending (time taken to send the request)
4. TTFB (time taken by server to send the response back - actual server processing time)
5. Downloading (time taken by browser to download the content)        

A) For each request I see following type of network calls: requestWillBeSent, responseReceived and loadingFinished. I assume that

• requestWillBeSent is logged when browser knows that the call have to be issued

yup 

• responseReceived is logged when the browser actually issues the request and start getting the response
  

yes. responseReceived is much later than when the request was issued. And yeah the first bytes of the response headers are being read.

• loadingFinished is logged when the browser completes loading
  

Close. technically the timestamp of loadingFinished comes from Blink, and if the main thread is busy, there could be a big gap between when the file finished in the network layer and when Blink has time to process its completion.

 
B) Each of those log messages have a timestamp. Can they be trusted for measuring performance?

They are blink-side timestamps.

The "timing" object's timestamps are collected in the network layer. For really accurate measurement, you'll want to know both. :)

 

C) I believe responseReceived.params.response.timing.XXXStart and XXXEnd are in ms. The difference between them indicates the time taken to perform that operation. Please confirm.

Yes. As Blaise alluded, the "timing" object is mostly ResourceTiming. Read that spec for more details.

 

D) From which point these timings (timing.XXXStart) are measured? Is it from responseReceived.params.response.timing.requestTime?

see https://w3c.github.io/resource-timing/#performanceresourcetiming

 

E) What does timing.receiveHeadersEnd indicates? Is it the total time taken from responseReceived.params.response.timing.requestTime till completion of request?

No idea, actually. It's nonstandard. poking around receiveHeadersEnd f:webkit package:chromium - Code Search might help

 

F) I believe these factors helps in measuring time slices 2, 3 and 4 above. Is it possible to measure 1 and 5?

Without checking much...

•  1 (queueing) is from requestWillBeSent until timing.fetchStart or maybe timing.requestStart
  
• 5 (time spent downloading).. Here's how devtools frontend calculates it
  

 

I tried other forums as well and finally landed here. Any pointers on this will be great.

Thanks Much, Raja

Looking at the source will be useful.. For instance you can walk the call heirarchy of loadingFinished to see when the timestamp is generated:

https://cs.chromium.org/chromium/src/third_party/WebKit/Source/core/fetch/ImageResource.cpp?sq=package:chromium&dr=CSs&rcl=1475522397&l=395

 

--

You received this message because you are subscribed to the Google Groups "Google Chrome Developer Tools" group.

To unsubscribe from this group and stop receiving emails from it, send an email to google-chrome-developer-tools+unsub...@googlegroups.com.

[Rajalingam Ramasamy]

Thanks a lot Blaise Bruer.

[Rajalingam Ramasamy]

Thanks a lot Paul Irish. I am able to follow through clearly now.

[Gayathri.R ece2016]

Hi Im using Chrome Performance logs to get all request details.Log contains only few request details and response (Network.ResponseReceived) data of some request is not getting logged.Is there any way to get log complete request details.