search

tsuyopon / webpagetest

Automatically exported from code.google.com/p/webpagetest
0 stars 0 forks source link

devtools2har for a warm-cache load of google.com produces a har that shows 15s load time instead of 1.5s #130

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
This is from the NodeJS agent. The DevTools Network and Page events are taken 
from the point where we already have http://www.google.com search results 
loaded in Chrome, right before we load http://www.google.com home page again.

I extracted all raw DevTools message timestamps from the JSON log, and the 
range is 1356676666.316071 - 1356676667.712409 -- ~1.5s, not 15s.

It seems there might be an issue with the timing inference for cached resources.

Original issue reported on code.google.com by k...@google.com on 28 Dec 2012 at 7:10

Attachments:

GoogleCodeExporter commented 9 years ago 
Here is what happens for e.g. tia.png -- Network.responseReceived has 
"timing":{"requestTime":1356676652.014448, which is probably what causes the 
start time in the HAR to be earlier than the beginning of page load.

It seems offhand that the start time for the HAR should be the "timestamp" from 
the Network.requestWillBeSent message with the matching "requestId".

{"method":"Network.requestWillBeSent","params":{"requestId":"67265.26","frameId"
:"67265.1","loaderId":"67265.5","documentURL":"http://www.goo
gle.com/","request":{"url":"http://www.google.com/textinputassistant/tia.png","m
ethod":"GET","headers":{}},"timestamp":1356676666.506212,"ini
tiator":{"type":"script","stackTrace":[{"functionName":"y.U","url":"http://www.g
oogle.com/xjs/_/js/s/c,sb,cr,vm,cdos,jsa,sf,tbpr,tbui,rsn,ob,
mb,lc,hv,cfm,klc,kat,aut,esp,erh,bihu,amcl,kp,lu,m,rtis,shb,sfa,hsm,j,p,pcc,csi/
rt=j/ver=3w99aWPP0po.en_US./d=1/sv=1/rs=AItRSTPrAylXrfkOPyRRY
-YioThBMqxW2A","lineNumber":476,"columnNumber":491},{"functionName":"_.zl.wi","u
rl":"http://www.google.com/xjs/_/js/s/c,sb,cr,vm,cdos,jsa,sf,
tbpr,tbui,rsn,ob,mb,lc,hv,cfm,klc,kat,aut,esp,erh,bihu,amcl,kp,lu,m,rtis,shb,sfa
,hsm,j,p,pcc,csi/rt=j/ver=3w99aWPP0po.en_US./d=1/sv=1/rs=AItR
STPrAylXrfkOPyRRY-YioThBMqxW2A","lineNumber":266,"columnNumber":46},{"functionNa
me":"O.a","url":"http://www.google.com/xjs/_/js/s/c,sb,cr,vm,
cdos,jsa,sf,tbpr,tbui,rsn,ob,mb,lc,hv,cfm,klc,kat,aut,esp,erh,bihu,amcl,kp,lu,m,
rtis,shb,sfa,hsm,j,p,pcc,csi/rt=j/ver=3w99aWPP0po.en_US./d=1/
sv=1/rs=AItRSTPrAylXrfkOPyRRY-YioThBMqxW2A","lineNumber":497,"columnNumber":489}
,{"functionName":"b","url":"http://www.google.com/xjs/_/js/s/
c,sb,cr,vm,cdos,jsa,sf,tbpr,tbui,rsn,ob,mb,lc,hv,cfm,klc,kat,aut,esp,erh,bihu,am
cl,kp,lu,m,rtis,shb,sfa,hsm,j,p,pcc,csi/rt=j/ver=3w99aWPP0po.
en_US./d=1/sv=1/rs=AItRSTPrAylXrfkOPyRRY-YioThBMqxW2A","lineNumber":443,"columnN
umber":269},{"functionName":"_.zl.Ap.a","url":"http://www.goo
gle.com/xjs/_/js/s/c,sb,cr,vm,cdos,jsa,sf,tbpr,tbui,rsn,ob,mb,lc,hv,cfm,klc,kat,
aut,esp,erh,bihu,amcl,kp,lu,m,rtis,shb,sfa,hsm,j,p,pcc,csi/rt
=j/ver=3w99aWPP0po.en_US./d=1/sv=1/rs=AItRSTPrAylXrfkOPyRRY-YioThBMqxW2A","lineN
umber":448,"columnNumber":131},{"functionName":"_.Df","url":"
http://www.google.com/xjs/_/js/s/c,sb,cr,vm,cdos,jsa,sf,tbpr,tbui,rsn,ob,mb,lc,h
v,cfm,klc,kat,aut,esp,erh,bihu,amcl,kp,lu,m,rtis,shb,sfa,hsm,
j,p,pcc,csi/rt=j/ver=3w99aWPP0po.en_US./d=1/sv=1/rs=AItRSTPrAylXrfkOPyRRY-YioThB
MqxW2A","lineNumber":83,"columnNumber":99},{"functionName":"w
indow.google.pmc.dispose.window.google.pmc","url":"http://www.google.com/xjs/_/j
s/s/c,sb,cr,vm,cdos,jsa,sf,tbpr,tbui,rsn,ob,mb,lc,hv,cfm,klc,
kat,aut,esp,erh,bihu,amcl,kp,lu,m,rtis,shb,sfa,hsm,j,p,pcc,csi/rt=j/ver=3w99aWPP
0po.en_US./d=1/sv=1/rs=AItRSTPrAylXrfkOPyRRY-YioThBMqxW2A","l
ineNumber":82,"columnNumber":288},{"functionName":"_.Ob._.zb.forEach.d","url":"h
ttp://www.google.com/xjs/_/js/s/c,sb,cr,vm,cdos,jsa,sf,tbpr,t
bui,rsn,ob,mb,lc,hv,cfm,klc,kat,aut,esp,erh,bihu,amcl,kp,lu,m,rtis,shb,sfa,hsm,j
,p,pcc,csi/rt=j/ver=3w99aWPP0po.en_US./d=1/sv=1/rs=AItRSTPrAy
lXrfkOPyRRY-YioThBMqxW2A","lineNumber":134,"columnNumber":449},{"functionName":"
_.Ff","url":"http://www.google.com/xjs/_/js/s/c,sb,cr,vm,cdos
,jsa,sf,tbpr,tbui,rsn,ob,mb,lc,hv,cfm,klc,kat,aut,esp,erh,bihu,amcl,kp,lu,m,rtis
,shb,sfa,hsm,j,p,pcc,csi/rt=j/ver=3w99aWPP0po.en_US./d=1/sv=1
/rs=AItRSTPrAylXrfkOPyRRY-YioThBMqxW2A","lineNumber":82,"columnNumber":262},{"fu
nctionName":"r","url":"http://www.google.com/","lineNumber":7
2,"columnNumber":5553},{"functionName":"","url":"http://www.google.com/xjs/_/js/
s/c,sb,cr,vm,cdos,jsa,sf,tbpr,tbui,rsn,ob,mb,lc,hv,cfm,klc,ka
t,aut,esp,erh,bihu,amcl,kp,lu,m,rtis,shb,sfa,hsm,j,p,pcc,csi/rt=j/ver=3w99aWPP0p
o.en_US./d=1/sv=1/rs=AItRSTPrAylXrfkOPyRRY-YioThBMqxW2A","lin
eNumber":1434,"columnNumber":118},{"functionName":"","url":"http://www.google.co
m/xjs/_/js/s/c,sb,cr,vm,cdos,jsa,sf,tbpr,tbui,rsn,ob,mb,lc,hv
,cfm,klc,kat,aut,esp,erh,bihu,amcl,kp,lu,m,rtis,shb,sfa,hsm,j,p,pcc,csi/rt=j/ver
=3w99aWPP0po.en_US./d=1/sv=1/rs=AItRSTPrAylXrfkOPyRRY-YioThBM
qxW2A","lineNumber":1443,"columnNumber":3}]}}},

{"method":"Network.requestServedFromCache","params":{"requestId":"67265.26"}},

{"method":"Network.responseReceived","params":{"requestId":"67265.26","frameId":
"67265.1","loaderId":"67265.5","timestamp":1356676666.506392,
"type":"Image","response":{"url":"http://www.google.com/textinputassistant/tia.p
ng","status":200,"statusText":"OK","headers":{"Date":"Fri, 28
 Dec 2012 04:07:21 GMT","X-Content-Type-Options":"nosniff","Last-Modified":"Mon, 02 Apr 2012 02:13:37 GMT","Server":"sffe","Age":"9010","Cont
ent-Type":"image/png","Cache-Control":"public, 
max-age=691200","Content-Length":"387","X-XSS-Protection":"1; 
mode=block","Expires":"Sat, 05 J
an 2013 04:07:21 
GMT"},"mimeType":"image/png","connectionReused":false,"connectionId":68,"fromDis
kCache":false,"timing":{"requestTime":135667
6652.014448,"proxyStart":-1,"proxyEnd":-1,"dnsStart":-1,"dnsEnd":-1,"connectStar
t":2,"connectEnd":2,"sslStart":-1,"sslEnd":-1,"sendStart":2,"
sendEnd":2,"receiveHeadersEnd":52},"headersText":"HTTP/1.1 200 
OK\r\nContent-Type: image/png\r\nLast-Modified: Mon, 02 Apr 2012 02:13:37 GMT\
r\nDate: Fri, 28 Dec 2012 04:07:21 GMT\r\nExpires: Sat, 05 Jan 2013 04:07:21 
GMT\r\nX-Content-Type-Options: nosniff\r\nServer: sffe\r\nConten
t-Length: 387\r\nX-XSS-Protection: 1; mode=block\r\nCache-Control: public, 
max-age=691200\r\nAge: 9010\r\n\r\n","requestHeaders":{"Accept-Cha
rset":"ISO-8859-1,utf-8;q=0.7,*;q=0.3","Accept-Encoding":"gzip,deflate,sdch","Ho
st":"www.google.com","Accept-Language":"en-US,en;q=0.8","User
-Agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) AppleWebKit/537.24 
(KHTML, like Gecko) Chrome/26.0.1371.0 Safari/537.24","X-Chrome-UM
A-Enabled":"1","X-Chrome-Variations":"COe1yQEIjLbJAQictskBCKa2yQEIp7bJAQi9tskBCP
aDygE=","Accept":"*/*","Referer":"http://www.google.com/","Co
okie":"PREF=ID=e2558c8480a1984b:FF=0:TM=1356676651:LM=1356676651:S=_39pD9UAGSJ0J
YxW; NID=67=djbfAVpfZfJ69gCe5PyK6gKky7-d0YhKK5zdwCDE4MdA5fhja
i8ngg8hUCu_0_rOB3d4r7R3-OwhT7_nqfg6p6T69ABWjmtnIFtm5ERn7oAXjNkdIU-Gj_geuXWiNJxY"
,"Connection":"keep-alive"},"requestHeadersText":"GET /textin
putassistant/tia.png HTTP/1.1\r\nHost: www.google.com\r\nConnection: 
keep-alive\r\nUser-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2)
 AppleWebKit/537.24 (KHTML, like Gecko) Chrome/26.0.1371.0 Safari/537.24\r\nAccept: */*\r\nX-Chrome-UMA-Enabled: 1\r\nX-Chrome-Variations: COe1yQEIjLbJAQictskBCKa2yQEIp7bJAQi9tskBCPaDygE=\r\nReferer: http://www.google.com/\r\nAccept-Encoding: gzip,deflate,sdch\r\nAccept-Language: en-US,en;q=0.8\r\nAccept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3\r\nCookie: PREF=ID=e2558c8480a1984b:FF=0:TM=1356676651:LM=1356676651:S=_39pD9UAGSJ0JYxW; NID=67=djbfAVpfZfJ69gCe5PyK6gKky7-d0YhKK5zdwCDE4MdA5fhjai8ngg8hUCu_0_rOB3d4r7R3-OwhT7_nqfg6p6T69ABWjmtnIFtm5ERn7oAXjNkdIU-Gj_geuXWiNJxY\r\n\r\n"}}},
{"method":"Network.dataReceived","params":{"requestId":"67265.26","timestamp":13
56676666.506472,"dataLength":387,"encodedDataLength":0}},
{"method":"Network.loadingFinished","params":{"requestId":"67265.26","timestamp"
:1356676666.506493}},

Original comment by k...@google.com on 28 Dec 2012 at 7:20

GoogleCodeExporter commented 9 years ago 
Summarizing klm's conclusion: It seems that devtools references the original 
response when providing details on response served from cache. Specifically, it 
does the following it sends the following triple. The odd thing about it is 
that devtools explicitly says request served from cache and the says served 
from disk cache is false.

    {
        "method": "Network.requestWillBeSent", 
        "params": {
            "documentURL": "http://www.google.com/", 
            "frameId": "67265.1", ...
            "loaderId": "67265.5", 
            "request": {
                "headers": {}, 
                "method": "GET", 
                "url": "http://www.google.com/images/srpr/logo3w.png"
            }, 
            "requestId": "67265.23", 
            "timestamp": 1356676666.442761
        }
    }, 
    {
        "method": "Network.requestServedFromCache", 
        "params": {
            "requestId": "67265.23"
        }
    }, 
    {
        "method": "Network.responseReceived", 
        "params": {
            "frameId": "67265.1", 
            "loaderId": "67265.5", 
            "requestId": "67265.23", 
            "response": {
                "connectionId": 49, 
                "connectionReused": false, 
                "fromDiskCache": false, 
                ...

Original comment by be...@chromium.org on 25 Feb 2013 at 9:00

GoogleCodeExporter commented 9 years ago 
We no longer convert the dev tools to an intermediate HAR.  We work on the dev 
tools logs natively.

Original comment by PatMee...@gmail.com on 4 Jul 2013 at 5:56