Phantomas npm module returning 0ms domComplete

[coryshaw]

Thanks for making this awesome tool! I used it for a new project (perfwars.com), and after launching it I realized that a lot of urls return 0ms domComplete, which I had to code a special case and error out for.

in node I'm using these flags with phantomas version 1.12.0 on ubuntu: phantomas(url, {'timeout':30, 'modules': 'windowPerformance', 'stop-at-onload': true}, function(err, json, results) {}

Here's an example of a url (sas.com) that returns 0ms domComplete about 80% of the time, captured in the console from the node app in debug mode (via DEBUG=phantomas* npm start):

As you can see, it returns no errors, yet 0ms domComplete.

After some experimentation, I realized that what was causing this was the "stop-at-onload": true flag...with that set sometimes onload fires before domComplete (which I would think is the indicator for onload).

Might be a bug, might not, but figured I'd let you know.

UPDATE: After testing more (this time with nytimes.com), even without the stop-at-onload flag, I still get a mix of 0ms domComplete and error code 252

I can also verify the bug when running it straight in the command line:

phantomas http://nytimes.com --reporter=json --modules=windowPerformance

UPDATE2 Here's some more urls that fail:

apicastor.com app.wlppr.co http://ft.com http://buzzfeed.com http://huffingtonpost.com http://walmart.com

Thanks again! Cory

[macbre]

@coryshaw, thanks for reporting the issue.

Can you try to run phantomas with --engine=webkit2 option? If it still does not work, please paste the full output when run with DEBUG=* environmental variable set and provide the gist link. Thanks!

[coryshaw]

Sure thing, I've actually been testing a lot this today using webkit2, and while some of the domains that normally fail using the default engine now return a proper number for domComplete, many still do not. Like this one fails every time: HTTP://BIEGNER-TECHNIK.DE

Output from the npm module in debug mode: https://gist.github.com/coryshaw/15614d2212e126b8b6b1

Output from the console using --debug flag: https://gist.github.com/coryshaw/3b225663657053e9608f

I also noticed that with most domains, the new timing data for performanceTimingConnect, performanceTimingDNS, and performanceTimingTTFB seem to always return 0.

Additionally, performanceTimingPageLoad returns 0, 1, 2, or 3 depending on the domain...none of which seem right.

Hope this helps. Let me know if you need any more info.

Thanks!

[macbre]

Sorry, I should have mentioned to use --verbose option as well. to have all the information available emitted to the log. Can you re-run phantomas and provide new gist? Thanks!

I've noticed the strange behavior of performanceTiming* metrics as well. They're zero most of the times - I'm considering reverting #567 as such values provide no useful data at all :)

[coryshaw]

Sure, here you go:

https://gist.github.com/coryshaw/7966af1c83e6e363fbe1

[macbre]

I think I've found where the issue is:

On the website where these metrics "work" we get the following (onInit PhantomJS event is fired fairly early and is able to grab all performance timing related events):

21:30:29.190 Loading progress: 10%
21:30:29.191 Event progress emitted
21:30:29.275 Event onResourceReceived emitted
21:30:29.284 phantomas scope injected
21:30:29.284 onInit: page object initialized
21:30:29.284 Event init emitted
21:30:29.286 Spying disabled - installing window.performance metrics
21:30:29.286 Performance timing: using native window.performance

However, on affected pages onInit is triggered at the end (what!?) of page load and simply can't measure performance timing metrics:

21:31:15.718 Loading progress: 100%
21:31:15.718 Event progress emitted
21:31:15.719 Page loading finished ("success")
21:31:15.719 Event loadFinished emitted
21:31:15.721 phantomas scope injected
21:31:15.722 onInit: page object initialized
21:31:15.722 Event init emitted
21:31:15.724 Spying disabled - installing window.performance metrics
21:31:15.724 Performance timing: using native window.performance

Thanks for the logs! I'll dive deeper into this issue in the next few days.

[coryshaw]

Any luck? Let me know if I can help in any way. Is the issue related to PhantomJS?

Users reported some more URLs that trigger 0ms domComplete, which I can duplicate locally:

https://www.reddit.com/ http://www.manta.com/ http://www.seek.com.au/

[macbre]

Unfortunately, no progress here.

[coryshaw]

Just wanted to report back after installing 1.14...this version seems to have significantly reduced the problem. About 90% of the sites that were reporting 0ms DomComplete now work properly. Thank you!

[macbre]

Great to hear that! Thanks!

[EFF]

Some of the websites you pointed out (manta and seek) are still reporting 0ms domComplete on osx as well (even with the latest release of phantom). Any idea of what these websites might have in common ?

[EFF]

In fact lots of metrics are at 0

see this gist for a verbose run in case it helps

[coryshaw]

Yeah, I can also confirm that manata.com and seek.com.au still return 0ms domComplete. I'm running it on Ubuntu. I also added a re-run hook because sometimes on the first run it returns 0ms, but if you run it again it returns a value.

[branpar]

First off, awesome tool. Starting to work on a project and am integrating this into the toolset. I ran it on a schedule once every 60 seconds for a minute hitting the same URL each time and sending the data to a data warehouse we have onsite for reporting. Of those 60 runs two of them resulted in domCompleteto report as 0. So it's happening for me as well. Two in 60 isn't major but any fix in progress is appreciated!

[macbre]

@branpar, thanks! Can you post here a URL that you're checking with phantomas?

If you can not make it public an output of phantomas run with --verbose option and DEBUG=* env variable set will be helpful.

[branpar]

At the moment it's an internal site I'm testing prior to production launch so I can't share the link. The verbose output is massive in size. Is there a specific block you'd like for me to share?

[macbre]

Please publish the full output on gist and paste here a link.

[macbre]

@coryshaw / @EFF from the list of URLs provided by @coryshaw back in 2015:

https://www.reddit.com/ http://www.manta.com/ http://www.seek.com.au/

I'm able to reproduce it on http://www.manta.com/ only:

$ ./bin/phantomas.js http://www.manta.com --verbose  2>&1 | grep -E 'recv|domComplete'
15:14:57.582 recv: HTTP 416 <http://www.manta.com/> [text/html]
15:14:57.582 Event recv emitted
15:14:57.837 recv: HTTP 200 <http://cdn.distilnetworks.com/css/distil.css> [text/css]
15:14:57.837 Event recv emitted
15:14:58.242 recv: HTTP 200 <http://cdn.distilnetworks.com/images/anomaly-detected.png> [image/png]
15:14:58.242 Event recv emitted
* domComplete: 0 ms

[macbre]

Well, it does. Using --phone option (passing iPhone user agent) makes phantomas report a more accurate metric value:

$ ./bin/phantomas.js http://www.manta.com --verbose --phone  2>&1 | grep 'domComplete'
15:18:42.800 Navigation Timing milestone: domComplete
...
* domComplete: 486 ms

[macbre]

Closing as all reported URLs report correct domComplete value.