Sitespeed metrics not reported

[fbusse]

Hi,

running the latest docker with Chrome I have issues with getting several speedindex parameters. They're missing 95% of the time, but sometimes get reported. Any way I can debug this?

This is what happens most of the time: $ docker run --privileged --shm-size=1g --rm -v "$(pwd)":/sitespeed.io sitespeedio/sitespeed.io -b chrome --speedIndex https://www.idealo.de Google Chrome 60.0.3112.66 beta Mozilla Firefox 54.0 [2017-07-18 12:13:17] INFO: Versions OS: linux 4.9.32-15.41.amzn1.x86_64 nodejs: v6.11.1 sitespeed.io: 5.4.3 browsertime: 1.5.3 coach: 0.34.1 [2017-07-18 12:13:17] INFO: Starting chrome for analysing https://www.idealo.de 3 time(s) [2017-07-18 12:13:17] INFO: Testing url https://www.idealo.de run 1 [2017-07-18 12:13:28] INFO: Testing url https://www.idealo.de run 2 [2017-07-18 12:13:37] INFO: Testing url https://www.idealo.de run 3 [2017-07-18 12:13:47] INFO: 73 requests, 1070.21 kb, backEndTime: 92ms (±4.59ms), firstPaint: 335ms (±5.10ms), firstVisualChange: 0ms (±0.00ms), DOMContentLoaded: 695ms (±23.54ms), Load: 1.08s (±55.04ms), speedIndex: 0 (±0.00), visualComplete85: 0ms (±0.00ms), lastVisualChange: 0ms (±0.00ms), rumSpeedIndex: 583 (±73.74) (3 runs) [2017-07-18 12:13:47] INFO: Render HTML for 1 page(s) [2017-07-18 12:13:49] INFO: HTML stored in /sitespeed.io/sitespeed-result/www.idealo.de/2017-07-18-12-13-17 [2017-07-18 12:13:49] INFO: Finished analysing https://www.idealo.de

This happens on rare occasion and I don't believe the numbers are correct at all (the --video was just a test and does not change things permanently): $ docker run --privileged --shm-size=1g --rm -v "$(pwd)":/sitespeed.io sitespeedio/sitespeed.io -b chrome --speedIndex --video https://www.idealo.de Google Chrome 60.0.3112.66 beta Mozilla Firefox 54.0 [2017-07-18 12:17:50] INFO: Versions OS: linux 4.9.32-15.41.amzn1.x86_64 nodejs: v6.11.1 sitespeed.io: 5.4.3 browsertime: 1.5.3 coach: 0.34.1 [2017-07-18 12:17:51] INFO: Starting chrome for analysing https://www.idealo.de 3 time(s) [2017-07-18 12:17:51] INFO: Testing url https://www.idealo.de run 1 [2017-07-18 12:18:05] INFO: Testing url https://www.idealo.de run 2 [2017-07-18 12:18:20] INFO: Testing url https://www.idealo.de run 3 [2017-07-18 12:18:34] INFO: 76 requests, 1073.45 kb, backEndTime: 119ms (±4.71ms), firstPaint: 568ms (±20.52ms), firstVisualChange: 222ms (±157.21ms), DOMContentLoaded: 1.08s (±111.00ms), Load: 1.68s (±183.28ms), speedIndex: 222 (±157.21), visualComplete85: 222ms (±157.21ms), lastVisualChange: 222ms (±157.21ms), rumSpeedIndex: 1110 (±55.07) (3 runs) [2017-07-18 12:18:35] INFO: Render HTML for 1 page(s) [2017-07-18 12:18:38] INFO: HTML stored in /sitespeed.io/sitespeed-result/www.idealo.de/2017-07-18-12-17-50 [2017-07-18 12:18:38] INFO: Finished analysing https://www.idealo.de

Firefox always works: $ docker run --privileged --shm-size=1g --rm -v "$(pwd)":/sitespeed.io sitespeedio/sitespeed.io -b firefox --speedIndex https://www.idealo.de Google Chrome 60.0.3112.66 beta Mozilla Firefox 54.0 [2017-07-18 12:15:38] INFO: Versions OS: linux 4.9.32-15.41.amzn1.x86_64 nodejs: v6.11.1 sitespeed.io: 5.4.3 browsertime: 1.5.3 coach: 0.34.1 [2017-07-18 12:15:39] INFO: Starting firefox for analysing https://www.idealo.de 3 time(s) [2017-07-18 12:15:39] INFO: Testing url https://www.idealo.de run 1 [2017-07-18 12:15:52] INFO: Testing url https://www.idealo.de run 2 [2017-07-18 12:16:04] INFO: Testing url https://www.idealo.de run 3 [2017-07-18 12:16:16] INFO: 80 requests, 1054.66 kb, backEndTime: 129ms (±31.48ms), firstVisualChange: 1.05s (±155.90ms), DOMContentLoaded: 1.73s (±216.01ms), Load: 2.91s (±282.29ms), speedIndex: 1690 (±147.48), visualComplete85: 1.95s (±142.89ms), lastVisualChange: 5.66s (±286.81ms), rumSpeedIndex: 1073 (±133.56) (3 runs) [2017-07-18 12:16:16] INFO: Render HTML for 1 page(s) [2017-07-18 12:16:18] INFO: HTML stored in /sitespeed.io/sitespeed-result/www.idealo.de/2017-07-18-12-15-38 [2017-07-18 12:16:18] INFO: Finished analysing https://www.idealo.de

Fridtjof

[soulgalore]

Hi @fbusse thanks for reporting. I'll try reproduce tonight, do you setup any connectivity with Docker networks or how do you handle connectivity? Did it start when you upgraded to latest version (meaning could it be something with latest Chrome beta)?

There's a hidden feature to keep the original video --browsertime.keepOriginalVideo , if you add that then if you can give me the original video for a run where it fails and I can check it out.

Best Peter

[fbusse]

Hi @soulgalore, It also happened with version 5.4.1 (from the drocker-compose install), I just upgraded to check for a bugfix in Chrome. I'm using native docker networking, no shaping etc. I'll try to get a video for you.

[soulgalore]

@fbusse thanks! We use VisualMetrics to analyze the video and get the metrics, so if we have a raw video its easier to test and report upstream if the problem isn't on our side.

[fbusse]

Had to add --video to actually get video files, but here they are: https://www.dropbox.com/s/gycbj40ut3hie0m/video.tar.gz?dl=1 Please let me know when you got the files.

[soulgalore]

Thanks, I've downloaded them now, do you know which run that failed (else I'll test all of them). I'll check tonight. I think it's something in our configuration for VisualMetrics that needs to be fine tuned.

I would use some kind of shaping (our docker networks shaping example works fine for me) to make it easier to find a regression and have consistent values, or how do you use the result/metrics?

Best Peter

[fbusse]

It's always the same ones: firstVisualChange, speedIndex and visualComplete. Either 0 or identical numbers.

[soulgalore]

@fbusse the identical numbers are probably because your native internet connection is fast. If you try https://www.sitespeed.io/documentation/sitespeed.io/browsers/#change-connectivity and set another profile I think you will see.

For the 0:s: The problem is is on our side, I tested one of the raw files with a default Visual Metrics on my local and there it works. Will look into it the coming days and fix it asap. Thanks for sharing the original files, really helpful!

[soulgalore]

The problem is here (our hack to fix the problem with Chrome updating the screen partly): https://github.com/sitespeedio/browsertime/blob/master/lib/support/video/visualMetrics.js#L17-L22

We have a long term fix coming up but that will take some time, so I'll check if I can do something simple the coming week.

[fbusse]

I switched to network shaping with docker (as per documentation). This is the result: $ docker run --privileged --shm-size=1g --network cable --rm -v "$(pwd)":/sitespeed.io sitespeedio/sitespeed.io -c cable -b chrome --speedIndex https://www.idealo.de Google Chrome 60.0.3112.66 beta Mozilla Firefox 54.0 [2017-07-19 11:03:03] INFO: Versions OS: linux 4.9.32-15.41.amzn1.x86_64 nodejs: v6.11.1 sitespeed.io: 5.4.3 browsertime: 1.5.3 coach: 0.34.1 [2017-07-19 11:03:03] INFO: Starting chrome for analysing https://www.idealo.de 3 time(s) [2017-07-19 11:03:03] INFO: Testing url https://www.idealo.de run 1 [2017-07-19 11:03:16] INFO: Testing url https://www.idealo.de run 2 [2017-07-19 11:03:25] INFO: Testing url https://www.idealo.de run 3 [2017-07-19 11:03:35] INFO: 76 requests, 1060.45 kb, backEndTime: 222ms (±4.77ms), firstPaint: 859ms (±52.36ms), firstVisualChange: 0ms (±0.00ms), DOMContentLoaded: 1.82s (±86.73ms), Load: 3.25s (±351.59ms), speedIndex: 0 (±0.00), visualComplete85: 0ms (±0.00ms), lastVisualChange: 0ms (±0.00ms), rumSpeedIndex: 2292 (±94.00) (3 runs) [2017-07-19 11:03:36] INFO: Render HTML for 1 page(s) [2017-07-19 11:03:38] INFO: HTML stored in /sitespeed.io/sitespeed-result/www.idealo.de/2017-07-19-11-03-03 [2017-07-19 11:03:38] INFO: Finished analysing https://www.idealo.de

[soulgalore]

@fbusse if you check the HAR file, can you see if the docker network worked (you have a much longer download time on the first response)? I've seen that sometimes the network doesn't work. If that's the case, recreate it again!

[fbusse]

I haven't had time to look at the HAR files, but just from the run-time of the command I'm quite certain that shaping works. 3G takes well over 2 minutes and gives speedindex data. Cable and native don't, at least not reliably.

[soulgalore]

ok, cool, let me look into the video again then.

[soulgalore]

I've pushed a fix in browsertime and will let it run for a day before we can release a fix release in sitespeed.

[fbusse]

@soulgalore I'll happily test the fix as soon as it is available. In the meantime, here's the archive from a run with wrong speed number (incl. browsertime.har): https://www.dropbox.com/s/djb58me7nqj5y3r/video.tar.gz?dl=1 Please let me know when you got it.

The run itself: $ docker run --privileged --shm-size=1g --network cable --rm -v "$(pwd)":/sitespeed.io sitespeedio/sitespeed.io -b chrome -c cable --video --speedIndex https://www.idealo.de Google Chrome 60.0.3112.66 beta Mozilla Firefox 54.0 [2017-07-20 07:18:47] INFO: Versions OS: linux 4.9.32-15.41.amzn1.x86_64 nodejs: v6.11.1 sitespeed.io: 5.4.3 browsertime: 1.5.3 coach: 0.34.1 [2017-07-20 07:18:47] INFO: Starting chrome for analysing https://www.idealo.de 3 time(s) [2017-07-20 07:18:47] INFO: Testing url https://www.idealo.de run 1 [2017-07-20 07:19:07] INFO: Testing url https://www.idealo.de run 2 [2017-07-20 07:19:29] INFO: Testing url https://www.idealo.de run 3 [2017-07-20 07:19:52] INFO: 71 requests, 1074.32 kb, backEndTime: 389ms (±69.14ms), firstPaint: 1.20s (±118.51ms), firstVisualChange: 478ms (±337.76ms), DOMContentLoaded: 2.23s (±200.37ms), Load: 3.47s (±336.19ms), speedIndex: 478 (±338.23), visualComplete85: 478ms (±337.76ms), lastVisualChange: 483ms (±341.77ms), rumSpeedIndex: 2749 (±255.92) (3 runs) [2017-07-20 07:19:52] INFO: Render HTML for 1 page(s) [2017-07-20 07:19:56] INFO: HTML stored in /sitespeed.io/sitespeed-result/www.idealo.de/2017-07-20-07-18-47 [2017-07-20 07:19:56] INFO: Finished analysing https://www.idealo.de

[soulgalore]

@fbusse hopefully the fix will also fix the wrong metrics. You can try it out now if you change to use the https://hub.docker.com/r/sitespeedio/sitespeed.io-autobuild/ Docker image, that is the one we use for https://dashboard.sitespeed.io to test our new builds.

[fbusse]

Autobuild looks better! The run takes quite a bit longer, but the numbers seem sane.

[fbusse]

But I'm seeing quite a few of these: [2017-07-20 11:56:28] ERROR: Couldn't generate the HAR from Firefox from the HAR Export Trigger. [2017-07-20 11:56:28] ERROR: ScriptTimeoutError: Timed out at WebDriverError (/usr/src/app/node_modules/selenium-webdriver/lib/error.js:27:5) at ScriptTimeoutError (/usr/src/app/node_modules/selenium-webdriver/lib/error.js:203:5) at Object.throwDecodedError (/usr/src/app/node_modules/selenium-webdriver/lib/error.js:489:11) at parseHttpResponse (/usr/src/app/node_modules/selenium-webdriver/lib/http.js:519:13) at doSend.then.response (/usr/src/app/node_modules/selenium-webdriver/lib/http.js:441:30) at process._tickCallback (internal/process/next_tick.js:109:7) at Driver.schedule (/usr/src/app/node_modules/selenium-webdriver/lib/webdriver.js:816:17) at Driver.executeAsyncScript (/usr/src/app/node_modules/selenium-webdriver/lib/webdriver.js:900:17) at Promise.try (/usr/src/app/node_modules/browsertime/lib/core/seleniumRunner.js:189:28)

[soulgalore]

You can increase the timeout for collecting the HAR with --timeouts.script but the default is set to 80 seconds so it is probably some problem in the HAR Export Trigger, and I guess it could be some content on the page. If you can track it down, please report it to the HAR export project.