_was_pushed in chrome is inconsistent

[worenga]

Currently, i am performing measurements with pages that use HTTP/2 Server push.

However, i found that the "_was_pushed" key in the har of browsertime is inaccurate or misleading.
Note for all Websites presented here i am not affiliated with any of them. They are just examples and came up in a scan.
I stumbled upon a multitude of anomalies here are some examples:

1. ) Example Website: https://erisrenee.com/

This website pushes 3 resources:

nghttp https://erisrenee.com -v | grep -C4 PUSH
[  0.601] recv (stream_id=13) :path: /assets/css/screen.css?v=84ca1c7d60
[  0.601] recv (stream_id=13) :scheme: https
[  0.601] recv (stream_id=13, sensitive) accept-encoding: gzip, deflate
[  0.601] recv (stream_id=13, sensitive) user-agent: nghttp2/1.14.0-DEV
[  0.601] recv PUSH_PROMISE frame <length=74, flags=0x04, stream_id=13>
          ; END_HEADERS
          (padlen=0, promised_stream_id=2)
[  0.601] recv (stream_id=13) :authority: erisrenee.com
[  0.601] recv (stream_id=13) :method: GET
[  0.601] recv (stream_id=13) :path: /assets/css/github.css?v=84ca1c7d60
[  0.601] recv (stream_id=13) :scheme: https
[  0.601] recv (stream_id=13, sensitive) accept-encoding: gzip, deflate
[  0.601] recv (stream_id=13, sensitive) user-agent: nghttp2/1.14.0-DEV
[  0.601] recv PUSH_PROMISE frame <length=74, flags=0x04, stream_id=13>
          ; END_HEADERS
          (padlen=0, promised_stream_id=4)
[  0.601] recv (stream_id=13) :authority: erisrenee.com
[  0.601] recv (stream_id=13) :method: GET
[  0.601] recv (stream_id=13) :path: /assets/js/index.js?v=84ca1c7d60
[  0.601] recv (stream_id=13) :scheme: https
[  0.601] recv (stream_id=13, sensitive) accept-encoding: gzip, deflate
[  0.601] recv (stream_id=13, sensitive) user-agent: nghttp2/1.14.0-DEV
[  0.601] recv PUSH_PROMISE frame <length=73, flags=0x04, stream_id=13>

/assets/css/screen.css?v=84ca1c7d60,
/assets/css/github.css?v=84ca1c7d60, and
/assets/js/index.js?v=84ca1c7d60.

Now lets open the page manually in chrome and see whether these resources appear in the network view.
Screenshot: https://www.dropbox.com/s/kj9aesotzxb7na3/Selection_006.png?dl=0
In this scenario it is a cloudflare-hosted website so cloudflare even tells us what has been pushed:

cf-h2-pushed:</assets/css/screen.css?v=84ca1c7d60>,</assets/css/github.css?v=84ca1c7d60>,</assets/js/index.js?v=84ca1c7d60>

As expected we discover the .css files, but where is the index.js?
A look into the source shows

<script data-rocketsrc="/assets/js/index.js?v=84ca1c7d60" type="text/rocketscript"></script>

So it is loaded using cloudflares rocket loader.
After a long search for the resource we find it is included in some XHR call.
Screenshot: https://www.dropbox.com/s/82qmlq3r1u6t214/Screenshot%20at%202017-02-07%2017%3A38%3A22.png?dl=0

Since the resource was pushed and is now requested again using javascript does that mean the push was useless? I don't know. But let's now request the page with browsertime.

➜  browsertime git:(master) ✗ mkdir enisrenee && cd enisrenee
➜  enisrenee git:(master) ✗ ../bin/browsertime.js https://erisrenee.com/
[2017-02-07 17:41:41] Running chrome for url: https://erisrenee.com/
[2017-02-07 17:41:41] Testing url https://erisrenee.com/ run 1
[2017-02-07 17:41:45] Testing url https://erisrenee.com/ run 2
[2017-02-07 17:41:49] Testing url https://erisrenee.com/ run 3
[2017-02-07 17:41:53] 24 requests, 308.33 kb, firstPaint: 1.15s (±36.03ms), DOMContentLoaded: 984ms (±44.63ms), Load: 1.21s (±35.43ms), rumSpeedIndex: 1145 (±36.03) (3 runs)
[2017-02-07 17:41:53] Wrote data to browsertime-results/erisrenee.com/2017-02-07T174141+0100

Now lets see whether any pushes were recorded in the har:

➜  enisrenee git:(master) ✗ cat browsertime-results/erisrenee.com/2017-02-07T174141+0100/browsertime.har | jq . | grep was_push | wc -l
0

Well weird that is weird. We know that resources are pushed from our previous exploration.

Lets see if we find the pushed resources.

➜  enisrenee git:(master) ✗ cat browsertime-results/erisrenee.com/2017-02-07T174141+0100/browsertime.har | jq -cr '.log.entries[] | .request.url' | grep github.css | wc -l
0
➜  enisrenee git:(master) ✗ cat browsertime-results/erisrenee.com/2017-02-07T174141+0100/browsertime.har | jq -cr '.log.entries[] | .request.url' | grep screen.css | wc -l
0
➜  enisrenee git:(master) ✗ cat browsertime-results/erisrenee.com/2017-02-07T174141+0100/browsertime.har | jq -cr '.log.entries[] | .request.url' | grep index.js          
https://erisrenee.com/cdn-cgi/pe/bag2?r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fjquery%2F1.12.2%2Fjquery.min.js&r[]=https%3A%2F%2Ferisrenee.com%2Fassets%2Fjs%2Findex.js%3Fv%3D84ca1c7d60&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fsmooth-scroll%2F9.1.2%2Fjs%2Fsmooth-scroll.min.js&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fhighlight.js%2F9.2.0%2Fhighlight.min.js
https://erisrenee.com/cdn-cgi/pe/bag2?r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fjquery%2F1.12.2%2Fjquery.min.js&r[]=https%3A%2F%2Ferisrenee.com%2Fassets%2Fjs%2Findex.js%3Fv%3D84ca1c7d60&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fsmooth-scroll%2F9.1.2%2Fjs%2Fsmooth-scroll.min.js&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fhighlight.js%2F9.2.0%2Fhighlight.min.js
https://erisrenee.com/cdn-cgi/pe/bag2?r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fjquery%2F1.12.2%2Fjquery.min.js&r[]=https%3A%2F%2Ferisrenee.com%2Fassets%2Fjs%2Findex.js%3Fv%3D84ca1c7d60&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fsmooth-scroll%2F9.1.2%2Fjs%2Fsmooth-scroll.min.js&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fhighlight.js%2F9.2.0%2Fhighlight.min.js

So we do not find the css files in the .har and only the rocket-loader request for the index.js.

Now lets look at the browsertime.json, maybe there are some clues what is going on.

➜  enisrenee git:(master) ✗ cat browsertime-results/erisrenee.com/2017-02-07T174141+0100/browsertime.json | jq . | grep screen.css
            "name": "https://erisrenee.com/assets/css/screen.css?v=84ca1c7d60",
            "name": "https://erisrenee.com/assets/css/screen.css?v=84ca1c7d60",
            "name": "https://erisrenee.com/assets/css/screen.css?v=84ca1c7d60",
            "name": "https://erisrenee.com/assets/css/screen.css?v=84ca1c7d60",
            "name": "https://erisrenee.com/assets/css/screen.css?v=84ca1c7d60",
            "name": "https://erisrenee.com/assets/css/screen.css?v=84ca1c7d60",
➜  enisrenee git:(master) ✗ cat browsertime-results/erisrenee.com/2017-02-07T174141+0100/browsertime.json | jq . | grep github.css
            "name": "https://erisrenee.com/assets/css/github.css?v=84ca1c7d60",
            "name": "https://erisrenee.com/assets/css/github.css?v=84ca1c7d60",
            "name": "https://erisrenee.com/assets/css/github.css?v=84ca1c7d60",
            "name": "https://erisrenee.com/assets/css/github.css?v=84ca1c7d60",
            "name": "https://erisrenee.com/assets/css/github.css?v=84ca1c7d60",
            "name": "https://erisrenee.com/assets/css/github.css?v=84ca1c7d60",
➜  enisrenee git:(master) ✗ cat browsertime-results/erisrenee.com/2017-02-07T174141+0100/browsertime.json | jq . | grep index.js  
            "name": "https://erisrenee.com/cdn-cgi/pe/bag2?r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fjquery%2F1.12.2%2Fjquery.min.js&r[]=https%3A%2F%2Ferisrenee.com%2Fassets%2Fjs%2Findex.js%3Fv%3D84ca1c7d60&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fsmooth-scroll%2F9.1.2%2Fjs%2Fsmooth-scroll.min.js&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fhighlight.js%2F9.2.0%2Fhighlight.min.js",
            "name": "https://erisrenee.com/assets/js/index.js?v=84ca1c7d60",
            "name": "https://erisrenee.com/cdn-cgi/pe/bag2?r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fjquery%2F1.12.2%2Fjquery.min.js&r[]=https%3A%2F%2Ferisrenee.com%2Fassets%2Fjs%2Findex.js%3Fv%3D84ca1c7d60&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fsmooth-scroll%2F9.1.2%2Fjs%2Fsmooth-scroll.min.js&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fhighlight.js%2F9.2.0%2Fhighlight.min.js",
            "name": "https://erisrenee.com/assets/js/index.js?v=84ca1c7d60",
            "name": "https://erisrenee.com/cdn-cgi/pe/bag2?r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fjquery%2F1.12.2%2Fjquery.min.js&r[]=https%3A%2F%2Ferisrenee.com%2Fassets%2Fjs%2Findex.js%3Fv%3D84ca1c7d60&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fsmooth-scroll%2F9.1.2%2Fjs%2Fsmooth-scroll.min.js&r[]=https%3A%2F%2Fcdnjs.cloudflare.com%2Fajax%2Flibs%2Fhighlight.js%2F9.2.0%2Fhighlight.min.js",
            "name": "https://erisrenee.com/assets/js/index.js?v=84ca1c7d60",

So the css appears twice each run with different timings and the index.js appears once for the push and once for the rocket loader. This is very weird.
HAR: https://gist.github.com/worenga/cfd6cfaefe606f27b37153f4e1d6bef2
JSON: https://gist.github.com/worenga/c3e6d6c2069c750e2dbf67efec3bbc76

2. ) Example
   Example Website: https://www.thecopycamp.com
   Again, not affiliated in any kind.
   Note that this website pushes 13 resources.

➜  ~ nghttp https://www.photographerstechsupport.com -v | grep PUSH
[  0.691] recv PUSH_PROMISE frame <length=91, flags=0x04, stream_id=13>
[  0.691] recv PUSH_PROMISE frame <length=104, flags=0x04, stream_id=13>
[  0.691] recv PUSH_PROMISE frame <length=90, flags=0x04, stream_id=13>
[  0.691] recv PUSH_PROMISE frame <length=96, flags=0x04, stream_id=13>
[  0.692] recv PUSH_PROMISE frame <length=88, flags=0x04, stream_id=13>
[  0.692] recv PUSH_PROMISE frame <length=96, flags=0x04, stream_id=13>
[  0.692] recv PUSH_PROMISE frame <length=94, flags=0x04, stream_id=13>
[  0.692] recv PUSH_PROMISE frame <length=93, flags=0x04, stream_id=13>
[  0.692] recv PUSH_PROMISE frame <length=110, flags=0x04, stream_id=13>
[  0.692] recv PUSH_PROMISE frame <length=103, flags=0x04, stream_id=13>
[  0.692] recv PUSH_PROMISE frame <length=103, flags=0x04, stream_id=13>
[  0.692] recv PUSH_PROMISE frame <length=104, flags=0x04, stream_id=13>
[  0.692] recv PUSH_PROMISE frame <length=86, flags=0x04, stream_id=13>
➜  ~ nghttp https://www.photographerstechsupport.com -v | grep PUSH | wc -l
13

Also in chrome we see 13 pushes:
https://www.dropbox.com/s/mt4q1tqe8ddgji3/Selection_009.png?dl=0

Now lets fetch this page using browsertime:

➜  browsertime git:(master) ✗ ./bin/browsertime.js https://www.photographerstechsupport.com 
[2017-02-07 18:29:41] Running chrome for url: https://www.photographerstechsupport.com
[2017-02-07 18:29:41] Testing url https://www.photographerstechsupport.com run 1
[2017-02-07 18:29:45] Testing url https://www.photographerstechsupport.com run 2
[2017-02-07 18:29:49] Testing url https://www.photographerstechsupport.com run 3
[2017-02-07 18:29:52] 9 requests, 110.11 kb, firstPaint: 807ms (±121.39ms), DOMContentLoaded: 820ms (±121.76ms), Load: 872ms (±123.10ms), rumSpeedIndex: 807 (±121.39) (3 runs)
[2017-02-07 18:29:52] Wrote data to browsertime-results/www.photographerstechsupport.com/2017-02-07T182941+0100

lets scan the HAR file

➜  browsertime git:(master) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-07T182941+0100/browsertime.har| jq . | grep -i push
              "name": "cf-h2-pushed",
              "name": "cf-h2-pushed",
        "_was_pushed": 1,
              "name": "cf-h2-pushed",
        "_was_pushed": 1,
        "_was_pushed": 1,

These are clearly not 13*3 resources...,

➜  browsertime git:(master) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-07T182941+0100/browsertime.har| jq  -r '.log.entries[] | select(contains({'_was_pushed'})) | "\(.pageref): \(.request.url)"'
page_1-1: https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery.js
page_1-1-1: https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery.js
page_1-1-1: https://www.photographerstechsupport.com/wp-content/themes/interface/js/jquery.cycle.all.min.js

So according to the har, in the 1st run nothing was pushed, in the 2nd run jquery.js was pushed and in the 3rd run jquery.js and jquery.cycle.all.min.js were pushed.

Now we know that for example jquery.js and style.css were pushed, but are they contained in the har?

➜  browsertime git:(master) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-07T182941+0100/browsertime.har| jq  -r '.log.entries[] | select(.request.url | contains("jquery.js")) | "\(.pageref): \(.request.url)"'  
page_1-1: https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery.js
page_1-1-1: https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery.js

➜  browsertime git:(master) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-07T182941+0100/browsertime.har| jq  -r '.log.entries[] | select(.request.url | contains("style.css")) | "\(.pageref): \(.request.url)"'  | wc -l
0

Now what about browsertime.json?

➜  browsertime git:(master) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-07T182941+0100/browsertime.json | jq . | grep style.css
            "name": "https://www.photographerstechsupport.com/wp-content/themes/interface/style.css",
            "name": "https://www.photographerstechsupport.com/wp-content/themes/interface/style.css",
            "name": "https://www.photographerstechsupport.com/wp-content/themes/interface/style.css",
➜  browsertime git:(master) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-07T182941+0100/browsertime.json | jq . | grep jquery.js 
            "name": "https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery.js",
            "name": "https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery.js",
            "name": "https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery.js",

This is weird as well.
HAR: https://gist.github.com/worenga/eae418783fde60278787806404775584
JSON: https://gist.github.com/worenga/371766ad2379f5b660c9f71e72dd7408

Is there a reliable way to tell which and whether resources have been pushed?

[soulgalore]

Hey @worenga
thanks for the report, we use pushStart/pushEnd in https://chromedevtools.github.io/debugger-protocol-viewer/tot/Network/#type-ResourceTiming but it could be that it doesn't work perfectly yet inside of Chrome (still marked as experimental), maybe we should remove it until it does.

Best
Peter

[worenga]

@soulgalore thanks for the reply. Regardless of whether pushStart/pushEnd is used, pushed responses should at least appear in the browsertime.har (c.f., Example 2)

[soulgalore]

Yes something seems wrong testing using Chrome and https://www.photographerstechsupport.com. Firefox gets the right amount of requests.

[worenga]

It seems entry._servedFromCache is (sometimes) true for pushed entries in chromePerflogParser.js
With options.skipEntriesFromDiskCache = true those are then filtered. see fix in #265.

This opens up the questions
a) Whether to not filter any pushed responses (But what if they were actually cached and pushed again?)

Here are some corner cases in which this might be useful to know, whether a push was cached or not:

• for some reason the server pushes the same resources twice.
• in the course of loading the page chrome requests two sub resources say page.xyz/subresource1 and page.xyz/subresource2 in both cases the server initiates pushes for the same resource, the latter might be in fact cached
• ... maybe even others.

b ) What is the default setting for cache config of a browsertime instance regarding chrome? Is the cache fully cold? Because I observed the following flags in the code: https://github.com/sitespeedio/browsertime/blob/master/lib/core/webdriver/chrome.js#L9
Which seem to be disabled, but im not that into the cache setting of chrome.

[tobli]

Thanks for deep diving into this, there's a lot of data and analysis to parse here! =) btw, I can't access your screen shots from Dropbox, seems they're not public. Could you run with --experimental.dumpChromePerflog to store the raw chrome data. We'd need that to check what data is available, and if we can parse it in a better way.

Regarding cache config - every run starts up a new, isolated session in Chrome, so there's no disk cache from a previous run to reuse. However we'd like to have the cache enabled, to make --preURLwork.

[tobli]

btw when debugging, running with -n 1should be enough, to get less data to analyse.

[worenga]

@tobli
thanks, i've exchanged the links to the screenshots.

Here is the files for https://www.photographerstechsupport.com/

➜  browsertime git:(f6eb84c) ✗ git checkout origin/master
➜  browsertime git:(f6eb84c) ✗ /home/bewo/Projects/chrome-sources/src/out/Default/chrome --version
Chromium 58.0.3006.0 
➜  browsertime git:(f6eb84c) ✗ ./bin/browsertime.js -n 1 --chrome.args="--ssl-version-max=tls1.2" --chrome.args="--disable-quic"  --chrome.binaryPath='/home/bewo/Projects/chrome-sources/src/out/Default/chrome' --experimental.dumpChromePerflog https://www.photographerstechsupport.com/
[2017-02-11 17:58:40] Running chrome for url: https://www.photographerstechsupport.com/
[2017-02-11 17:58:40] Testing url https://www.photographerstechsupport.com/ run 1
[2017-02-11 17:58:46] 16 requests, 154.98 kb, firstPaint: 1.16s, DOMContentLoaded: 1.18s, Load: 1.28s, rumSpeedIndex: 1159
[2017-02-11 17:58:46] Wrote data to browsertime-results/www.photographerstechsupport.com/2017-02-11T175840+0100
➜  browsertime git:(f6eb84c) ✗ # Note only 16 requests with http/2
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-11T175840+0100/browsertime.har | jq . | grep was_push | wc -l
7
➜  browsertime git:(f6eb84c) ✗ # this are not all resources...
➜  browsertime git:(f6eb84c) ✗ # the page pushes 13 resources 

➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-11T175840+0100/chromePerflog-0.json| jq . | gist
https://gist.github.com/worenga/755ef79964aff03b1b7242a6dadf2d9c
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-11T175840+0100/browsertime.har| jq . | gist 
https://gist.github.com/worenga/b53ccc1344c8d8a14876c05faf7e8893
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-11T175840+0100/browsertime.json| jq . | gist
https://gist.github.com/worenga/0b3103b3d6b3044707d637c9e68d69c6

➜  browsertime git:(f6eb84c) ✗ # just fetch http/1.1 enabled site for side-by-side comparison, (http1 has no push)
➜  browsertime git:(f6eb84c) ✗ ./bin/browsertime.js -n 1 --chrome.args="--ssl-version-max=tls1.2" --chrome.args="--disable-quic" --chrome.args="--disable-http2" --chrome.binaryPath='/home/bewo/Projects/chrome-sources/src/out/Default/chrome' --experimental.dumpChromePerflog https://www.photographerstechsupport.com/  
[2017-02-11 18:01:31] Running chrome for url: https://www.photographerstechsupport.com/
[2017-02-11 18:01:31] Testing url https://www.photographerstechsupport.com/ run 1
[2017-02-11 18:01:36] 22 requests, 181.02 kb, firstPaint: 1.19s, DOMContentLoaded: 1.s, Load: 1.s, rumSpeedIndex: 1186
[2017-02-11 18:01:36] Wrote data to browsertime-results/www.photographerstechsupport.com/2017-02-11T180131+0100
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-11T180131+0100/browsertime.har | jq . | gist
https://gist.github.com/worenga/27332305873e56905292f809d002d73f
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-11T180131+0100/browsertime.json| jq . | gist
https://gist.github.com/worenga/68dee1a43ea5fe828937308f69318fee
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-11T180131+0100/chromePerflog-0.json| jq . | gist
https://gist.github.com/worenga/e337efe3fb3bc3e299b468ae207bef2d

And here for https://www.erisrenee.com.

➜  browsertime git:(f6eb84c) ✗ ./bin/browsertime.js -n 1 --chrome.args="--ssl-version-max=tls1.2" --chrome.args="--disable-quic" --chrome.binaryPath='/home/bewo/Projects/chrome-sources/src/out/Default/chrome' --experimental.dumpChromePerflog https://www.erisrenee.com                  
[2017-02-11 18:07:59] Running chrome for url: https://www.erisrenee.com
[2017-02-11 18:07:59] Testing url https://www.erisrenee.com run 1
[2017-02-11 18:08:06] 25 requests, 306.99 kb, firstPaint: 2.17s, DOMContentLoaded: 1.91s, Load: 2.27s, rumSpeedIndex: 2166
[2017-02-11 18:08:06] Wrote data to browsertime-results/www.erisrenee.com/2017-02-11T180759+0100
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.erisrenee.com/2017-02-11T180759+0100/browsertime.har| jq . | grep was_push | wc -l
0
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.erisrenee.com/2017-02-11T180759+0100/browsertime.har| jq . | gist
https://gist.github.com/worenga/c838805c1bb57397a6df83030f84b901
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.erisrenee.com/2017-02-11T180759+0100/browsertime.json| jq . | gist
https://gist.github.com/worenga/65438d83c8f46319f2486f3ed14c7242
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.erisrenee.com/2017-02-11T180759+0100/chromePerflog-0.json|jq . |gist
https://gist.github.com/worenga/60957c27c43d95642094be4f0746c22e


➜  browsertime git:(f6eb84c) ✗ ./bin/browsertime.js -n 1 --chrome.args="--ssl-version-max=tls1.2" --chrome.args="--disable-quic" --chrome.args="--disable-http2" --chrome.binaryPath='/home/bewo/Projects/chrome-sources/src/out/Default/chrome' --experimental.dumpChromePerflog https://www.erisrenee.com
[2017-02-11 18:09:52] Running chrome for url: https://www.erisrenee.com
[2017-02-11 18:09:52] Testing url https://www.erisrenee.com run 1
[2017-02-11 18:09:59] 28 requests, 319.20 kb, firstPaint: 2.s, DOMContentLoaded: 2.62s, Load: 3.07s, rumSpeedIndex: 2898
[2017-02-11 18:09:59] Wrote data to browsertime-results/www.erisrenee.com/2017-02-11T180952+0100
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.erisrenee.com/2017-02-11T180952+0100/browsertime.har| jq .| gist
https://gist.github.com/worenga/d78266bc6453e0912a36521e76cc0955
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.erisrenee.com/2017-02-11T180952+0100/browsertime.json | jq . | gist
https://gist.github.com/worenga/20417bac083ecb5213a587d29083e805
➜  browsertime git:(f6eb84c) ✗ cat browsertime-results/www.erisrenee.com/2017-02-11T180952+0100/chromePerflog-0.json| jq . | gist
https://gist.github.com/worenga/d3fb709fd0c60212b8b5cda7df8a90ed

If you need more examples i have a larger dataset of pages that use push.

[tobli]

Looking at the https://www.photographerstechsupport.com/ results, the data we get from Chrome is hard to interpret:

• we receive the response for jquery.form.min.js at the time stamp 46201.121348 (https://gist.github.com/worenga/755ef79964aff03b1b7242a6dadf2d9c#file-gistfile-txt-L2008)
• we receive data for that js file at 46201.121526 (https://gist.github.com/worenga/755ef79964aff03b1b7242a6dadf2d9c#file-gistfile-txt-L2155)
• next loading has finished at 46201.109799, before we even got the response or received the data! (https://gist.github.com/worenga/755ef79964aff03b1b7242a6dadf2d9c#file-gistfile-txt-L2163)

[tobli]

@worenga would you able to test a PR from git? (#267) It seems to give better results for me, but I'd love some more testing.

[worenga]

Excellent, will patch our testbed to include perflogs and will schedule it to run on a larger set tomorrow.

[worenga]

I tested this for > 500 pages i know use push.
For the majority now at least i can observe one pushed resource in the generated .har, allthough I have to verify if that are in fact all resources that are pushed.

For our two testpages in the previous example https://www.erisrenee.com it does not look like the list is complete:

I know the page pushes 3 resources:
/assets/css/screen.v=84ca1c7d60
/assets/css/github.css?v=84ca1c7d60
/assets/js/index.js?v=84ca1c7d60
from manual inspection in chrome and nghttp2.

➜  browsertime git:(261-detect-push) ✗ ./bin/browsertime.js -n 1 --chrome.args="--ssl-version-max=tls1.2"  --chrome.args="--disable-quic"  --chrome.binaryPath='/home/bewo/Projects/chrome-sources/src/out/Default/chrome' --experimental.dumpChromePerflog  https://erisrenee.com/         
[2017-02-13 09:49:57] Running chrome for url: https://erisrenee.com/
[2017-02-13 09:49:57] Testing url https://erisrenee.com/ run 1
[2017-02-13 09:50:02] 25 requests, 309.40 kb, firstPaint: 1.24s, DOMContentLoaded: 959ms, Load: 1.34s, rumSpeedIndex: 1243
[2017-02-13 09:50:02] Wrote data to browsertime-results/erisrenee.com/2017-02-13T094957+0100
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/erisrenee.com/2017-02-13T094957+0100/browsertime.har | jq . | grep was_pushed
        "_was_pushed": 1,
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/erisrenee.com/2017-02-13T094957+0100/browsertime.har | jq . | grep was_pushed
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/erisrenee.com/2017-02-13T094957+0100/browsertime.har| jq . | gist 
https://gist.github.com/worenga/94de4f56b4c1993042d3f1c35f08f3a4
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/erisrenee.com/2017-02-13T094957+0100/browsertime.json| jq . | gist
https://gist.github.com/worenga/700a729d35099a327b51214477b5dc38
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/erisrenee.com/2017-02-13T094957+0100/chromePerflog-0.json | jq . | gist 
https://gist.github.com/worenga/6a44c041bb08bd82d291e189b0ba54ea

vs. http1:

➜  browsertime git:(261-detect-push) ✗ ./bin/browsertime.js -n 1 --chrome.args="--ssl-version-max=tls1.2"  --chrome.args="--disable-http2" --chrome.args="--disable-quic"  --chrome.binaryPath='/home/bewo/Projects/chrome-sources/src/out/Default/chrome' --experimental.dumpChromePerflog  https://erisrenee.com/ 
[2017-02-13 09:51:35] Running chrome for url: https://erisrenee.com/
[2017-02-13 09:51:35] Testing url https://erisrenee.com/ run 1
[2017-02-13 09:51:40] 27 requests, 318.94 kb, firstPaint: 1.67s, DOMContentLoaded: 1.s, Load: 1.77s, rumSpeedIndex: 1669
[2017-02-13 09:51:40] Wrote data to browsertime-results/erisrenee.com/2017-02-13T095135+0100
➜  browsertime git:(261-detect-push) ✗ 
➜  browsertime git:(261-detect-push) ✗ 
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/erisrenee.com/2017-02-13T095135+0100/browsertime.har | jq . | gist 
https://gist.github.com/worenga/07a460eb20c0e77efcfd92a937724af8
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/erisrenee.com/2017-02-13T095135+0100/browsertime.json | jq . | gist
https://gist.github.com/worenga/1fd4d6ca4f82af83f2094cdc56a26b9f
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/erisrenee.com/2017-02-13T095135+0100/browsertime.json| jq . | gist 
https://gist.github.com/worenga/b09fd0e0e3deddb1adbed5909a43de86

Note how it sais 27 requests in the http1 case and 25 requests in the http2 case.

Same is true for the photographerstechsupport page we observed previously.

➜  browsertime git:(261-detect-push) ✗ ./bin/browsertime.js -n 1 --chrome.args="--ssl-version-max=tls1.2"  --chrome.args="--disable-quic"  --chrome.binaryPath='/home/bewo/Projects/chrome-sources/src/out/Default/chrome' --experimental.dumpChromePerflog https://www.photographerstechsupport.com   
[2017-02-13 09:58:54] Running chrome for url: https://www.photographerstechsupport.com
[2017-02-13 09:58:54] Testing url https://www.photographerstechsupport.com run 1
[2017-02-13 09:58:59] 18 requests, 163.35 kb, firstPaint: 1.11s, DOMContentLoaded: 1.13s, Load: 1.23s, rumSpeedIndex: 1113
[2017-02-13 09:58:59] Wrote data to browsertime-results/www.photographerstechsupport.com/2017-02-13T095854+0100

vs http1

➜  browsertime git:(261-detect-push) ✗ ./bin/browsertime.js -n 1 --chrome.args="--ssl-version-max=tls1.2"  --chrome.args="--disable-http2" --chrome.args="--disable-quic"  --chrome.binaryPath='/home/bewo/Projects/chrome-sources/src/out/Default/chrome' --experimental.dumpChromePerflog https://www.photographerstechsupport.com 
[2017-02-13 09:58:43] Running chrome for url: https://www.photographerstechsupport.com
[2017-02-13 09:58:43] Testing url https://www.photographerstechsupport.com run 1
[2017-02-13 09:58:47] 22 requests, 181.02 kb, firstPaint: 1.08s, DOMContentLoaded: 1.s, Load: 1.21s, rumSpeedIndex: 1085
[2017-02-13 09:58:47] Wrote data to browsertime-results/www.photographerstechsupport.com/2017-02-13T095842+0100

If we compare the amount of resources for http1 and http2 from resourceTimings are the same

➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-13T095854+0100/browsertime.json browsertime-results/www.photographerstechsupport.com/2017-02-13T095842+0100/browsertime.json | jq -r '.browserScripts[0].timings.resourceTimings[] | .name' | grep "https://www.photographerstechsupport.com" | sort | uniq -c 
      2 https://www.photographerstechsupport.com/favicon.ico
      2 https://www.photographerstechsupport.com/wp-content/plugins/contact-form-7/includes/css/styles.css
      2 https://www.photographerstechsupport.com/wp-content/plugins/contact-form-7/includes/js/jquery.form.min.js
      2 https://www.photographerstechsupport.com/wp-content/plugins/contact-form-7/includes/js/scripts.js
      2 https://www.photographerstechsupport.com/wp-content/themes/interface/css/responsive.css
      2 https://www.photographerstechsupport.com/wp-content/themes/interface/font/Genericons.woff
      2 https://www.photographerstechsupport.com/wp-content/themes/interface/js/backtotop.js
      2 https://www.photographerstechsupport.com/wp-content/themes/interface/js/interface-slider-setting.js
      2 https://www.photographerstechsupport.com/wp-content/themes/interface/js/jquery.cycle.all.min.js
      2 https://www.photographerstechsupport.com/wp-content/themes/interface/js/scripts.js
      2 https://www.photographerstechsupport.com/wp-content/themes/interface/style.css
      2 https://www.photographerstechsupport.com/wp-content/uploads/2014/10/TOGAF-Certified.png
      2 https://www.photographerstechsupport.com/wp-content/uploads/2016/09/Amazon-Web-Certified-Architect-Sysop-Developer-Associate.png
      2 https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery.js
      2 https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery-migrate.min.js
      2 https://www.photographerstechsupport.com/wp-includes/js/wp-embed.min.js
      2 https://www.photographerstechsupport.com/wp-includes/js/wp-emoji-release.min.js
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-13T095854+0100/browsertime.json browsertime-results/www.photographerstechsupport.com/2017-02-13T095842+0100/browsertime.json | jq -r '.browserScripts[0].timings.resourceTimings[] | .name' | grep "https://www.photographerstechsupport.com" | sort | uniq -c  | wc -l
17

We know the page pushes:

https://www.photographerstechsupport.com/wp-includes/js/wp-emoji-release.min.js
https://www.photographerstechsupport.com/wp-content/plugins/contact-form-7/includes/css/styles.css
https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery-migrate.min.js
https://www.photographerstechsupport.com/wp-includes/js/wp-embed.min.js
https://www.photographerstechsupport.com/wp-content/themes/interface/css/responsive.css
https://www.photographerstechsupport.com/wp-content/themes/interface/js/backtotop.js
https://www.photographerstechsupport.com/wp-content/themes/interface/style.css
https://www.photographerstechsupport.com/wp-content/plugins/contact-form-7/includes/js/scripts.js
https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery.js
https://www.photographerstechsupport.com/wp-content/themes/interface/js/scripts.js
https://www.photographerstechsupport.com/wp-content/themes/interface/js/jquery.cycle.all.min.js
https://www.photographerstechsupport.com/wp-content/themes/interface/js/interface-slider-setting.js
https://www.photographerstechsupport.com/wp-content/plugins/contact-form-7/includes/js/jquery.form.min.js

But in the har we see annotated with pushed:

➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-13T095854+0100/browsertime.har | jq -rc '.log.entries[] | select(contains({_was_pushed})).request.url'
https://www.photographerstechsupport.com/wp-content/plugins/contact-form-7/includes/css/styles.css
https://www.photographerstechsupport.com/wp-content/themes/interface/style.css
https://www.photographerstechsupport.com/wp-content/themes/interface/css/responsive.css
https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery.js
https://www.photographerstechsupport.com/wp-includes/js/jquery/jquery-migrate.min.js
https://www.photographerstechsupport.com/wp-content/themes/interface/js/backtotop.js
https://www.photographerstechsupport.com/wp-content/themes/interface/js/scripts.js
https://www.photographerstechsupport.com/wp-content/themes/interface/js/jquery.cycle.all.min.js
https://www.photographerstechsupport.com/wp-content/themes/interface/js/interface-slider-setting.js

here are the logfiles for http2

➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-13T095854+0100/browsertime.har | jq . | gist
https://gist.github.com/worenga/47d6d9355130df8e1d49386ef90f4435
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-13T095854+0100/chromePerflog-0.json| jq . | gist
https://gist.github.com/worenga/8586d4bd58822c37218921e065f378dc
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.photographerstechsupport.com/2017-02-13T095854+0100/browsertime.json| jq . | gist
https://gist.github.com/worenga/008af24b90b604814de7ae2be937e49a

In my dataset there are also however, still some cases where the page pushes content but it is not annotated.
For example https://www.smartloanchoice.org

➜  browsertime git:(261-detect-push) ✗ ./bin/browsertime.js -n 1 --chrome.args="--ssl-version-max=tls1.2"  --chrome.args="--disable-quic"  --chrome.binaryPath='/home/bewo/Projects/chrome-sources/src/out/Default/chrome' --experimental.dumpChromePerflog https://www.smartloanchoice.org 
[2017-02-13 09:27:48] Running chrome for url: https://www.smartloanchoice.org
[2017-02-13 09:27:48] Testing url https://www.smartloanchoice.org run 1
[2017-02-13 09:27:53] 45 requests, 253.12 kb, firstPaint: 967ms, DOMContentLoaded: 994ms, Load: 1.73s, rumSpeedIndex: 1066
[2017-02-13 09:27:53] Wrote data to browsertime-results/www.smartloanchoice.org/2017-02-13T092748+0100
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.smartloanchoice.org/2017-02-13T092748+0100/browsertime.har | jq . | grep was_pushed | wc -l
0
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.smartloanchoice.org/2017-02-13T092748+0100/browsertime.har | jq . | grep 113-logo.png      
              "value": "</images/113-logo.png>"
➜  browsertime git:(261-detect-push) ✗ #thats just some header value but not our url-entry.
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.smartloanchoice.org/2017-02-13T092748+0100/browsertime.json | jq . | grep 113-logo.png
            "name": "https://www.smartloanchoice.org/images/113-logo.png",
➜  browsertime git:(261-detect-push) ✗# here we find it...
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.smartloanchoice.org/2017-02-13T092748+0100/chromePerflog-0.json| jq . | grep pushStart
          "pushStart": 0,
...
          "pushStart": 0,
          "pushStart": 178688.932239,
...


➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.smartloanchoice.org/2017-02-13T092748+0100/browsertime.har | jq . | gist
https://gist.github.com/worenga/7d8378051f8f1dd78b96f0bbeeb070cd
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.smartloanchoice.org/2017-02-13T092748+0100/browsertime.json| jq . | gist
https://gist.github.com/worenga/2a3f03b8ceafa923dd8c57a8fb8c6459
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.smartloanchoice.org/2017-02-13T092748+0100/chromePerflog-0.json | jq . | gist
https://gist.github.com/worenga/89cfc5a4ffc84a498b5db16a01556505

compare it again to http/1

➜  browsertime git:(261-detect-push) ✗# http/1 for comparison:
➜  browsertime git:(261-detect-push) ✗ ./bin/browsertime.js -n 1 --chrome.args="--ssl-version-max=tls1.2"  --chrome.args="--disable-http2" --chrome.args="--disable-quic"  --chrome.binaryPath='/home/bewo/Projects/chrome-sources/src/out/Default/chrome' --experimental.dumpChromePerflog https://www.smartloanchoice.org 
[2017-02-13 09:30:07] Running chrome for url: https://www.smartloanchoice.org
[2017-02-13 09:30:07] Testing url https://www.smartloanchoice.org run 1
[2017-02-13 09:30:12] 45 requests, 270.79 kb, firstPaint: 897ms, DOMContentLoaded: 909ms, Load: 1.67s, rumSpeedIndex: 1037
[2017-02-13 09:30:12] Wrote data to browsertime-results/www.smartloanchoice.org/2017-02-13T093007+0100
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.smartloanchoice.org/2017-02-13T093007+0100/browsertime.har | jq . | grep 113-logo
              "value": "</images/113-logo.png>; rel=preload; as=image\n<//html5shiv.googlecode.com/svn/trunk/html5.js>; rel=preload; as=script\n<//ajax.googleapis.com/ajax/libs/jquery/1.9.1/jquery.min.js>; rel=preload; as=script\n<//www.envoyhub.com/js/jquery.cycle2.min.js>; rel=preload; as=script\n<//www.envoyhub.com/js/jquery.cycle2.carousel.min.js>; rel=preload; as=script\n<//www.googleadservices.com/pagead/conversion.js>; rel=preload; as=script\n<//www.envoyhub.com/css/base-1.2.min.css>; rel=preload; as=style\n<//www.envoyhub.com/css/article.css>; rel=preload; as=style\n<//www.envoyhub.com/fonts/cta-set.css>; rel=preload; as=style"
          "url": "https://www.smartloanchoice.org/images/113-logo.png",
➜  browsertime git:(261-detect-push) ✗ #there is our resource
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.smartloanchoice.org/2017-02-13T093007+0100/browsertime.har | jq . | gist         
https://gist.github.com/worenga/6f8ad152012e12965e7ef68356501603
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.smartloanchoice.org/2017-02-13T093007+0100/browsertime.json | jq . | gist
https://gist.github.com/worenga/b8653ecb67428800b2edbb5471658d07
➜  browsertime git:(261-detect-push) ✗ cat browsertime-results/www.smartloanchoice.org/2017-02-13T093007+0100/chromePerflog-0.json | jq . | gist
https://gist.github.com/worenga/1c860984f7fca32e0fc99b8df9206666

[worenga]

Some other tests showed that the perflog is not really a good choice for the analysis of pushed objects.
Sometimes pushed resources do even not appear in the raw perflog, i am not sure if that is intended.
I will switch to exporting the raw netlog for my purpose.
Moreoever, i am not sure to whom to talk to at chromium about that.