Weird values for t_done/t_page and nt_domcomp

[joelabrahamsson]

I'm seeing really weird values reported back to the beacon. About 90% looks just about right. But then 10% have t_done and t_page values ranging from a couple of minutes up to 10 hours. It doesn't seem to be limited to any specific browser or version. In most, but not all, such cases the nt plugin also reports high values for nt_domcomp.

We have a bunch of other custom timers placed in head and stopped throughout the page, including one just below body and their values look sensible. For instance, for one page view made with Mobile Safari 8 we got:
t_resp: null
t_page: 69160352
t_done: 69160352
domComplete_minus_domContentLoadedEventEnd: 9263870 (calculated value base on navigation timings reported)
t_syncPage: 685 (custom timer started in head and completed just before )

Any thoughts about what could be going on?

I should add that the site is not a single page app but does load quit a lot of things on the client, including:

• ads
• content fetch asynchronously, typically after onLoad
• images fetch asynchronously, typically after onLoad
• Often, but not always, Facebook likes count etc

When I compare with another RUM tool, Pingdom, our average numbers using Boomerang is waaaaay higher and median numbers are about 20%. However, if I exclude the 95% percentile and calculate median on the rest I get pretty much the same numbers.

[bluesmoon]

I don't know about other browsers, but from what I've seen, Safari (including Mobile Safari)'s implementation of Navigation Timing is very broken.

[joelabrahamsson]

I see. About 95% of the weird page views is from browsers implementing NT. About 75% of those are mobile Safari and the rest are either the stock Android browser or Chrome on iOS or Android.

Given that, do you have any recommendation on what we should do? Would simply removing the nt plugin be enough?

[bluesmoon]

No, the rt plugin uses NT when available even if the nt plugin is not present. We'd want to patch boomerang against buggy browsers. Could you try drilling down some more to find some patterns?

[joelabrahamsson]

Gladly! However, I've already been drilling for a while without finding any clear patterns.

Out of 158 page views with t_done higher than 120000 the browser distribution is:
Mobile Safari 8: 107
Android 4: 38
Mobile Safari 7: 3
Chrome 38: 3
Chrome 28: 2
Mobile Safari 4: 1
Chrome 18: 1
Chrome 26: 1
Chrome 37: 1

It should be said that the traffic is almost exclusively from tablets meaning that a huge chunk of the traffic is from iPad and Mobile Safari.

I'll keep digging on my end but so any pointers on things to log and look for specifically would be great.

[joelabrahamsson]

Not a very clear patten but out of 33119 page views 12945 have a t_resp value. Out of 125 page views with weird t_done value only 14 have a t_resp value. So, those page views with weird t_done values seem to lack a t_resp value to a greater extent.

[crashbob]

Been digging into what seems to be the same issue as mentioned here and possibly also in issue

#35

and in issue

#43

Not being too familiar with the code, I hesitate to submit a patch, but I think I've located the problem.

First, my symptoms...

When a page loads, 2 beacons are fired. The first beacon has timing for the time in between (+/_) the last page load and clicking a link. So often this is several seconds or minutes, depending on how long the user waited between clicks. The first beacon also has the rt.quit flag set.

This first beacon is being fired by the unload event. But according to the notes, it should only be fired only if the user aborts the page load in some way before the page_ready fires. This beacon, however, is being fired most every time in my tests. This causes extra beacons, extra data, and large t_done times.

The line of code in question was introduced in 239bbd0 from April 2014. Not sure if this fits everyone's timeline, or if some additional trigger in a later commit actually exposed the issue. The commit message says:

       Call done() on unload as well just in case the user left the page before …
                 the onload event fired.

       We will only send a beacon if unload fired before onload, and will include
                 a rt.abrt flag on the beacon.

But the code looks like this: (line 553 of rt.js from the most recent commit)

    if(!this.unloadfired) {
        // run done on abort or on page_unload to measure session length
        BOOMR.plugins.RT.done(edata, "unload");
    }

According to the comments, we should be checking for "this.onloadfired", rather than this.unloadfired. Switch that little "u" to an "o" and the double beacons and false timings go away in my tests.

We saw the problem in actual production code as we were testing implementation of boomerang, but the problem can easily be duplicated by simply adding an appropriate beacon URL to any of the "howto" docs pages and then refreshing it, or add it to multiple of them and click between them. Your webserver accepting the beacon, or the console logs will show the extra beacon.

Again, I'd consider submitting a patch, but it is 1 letter, and I'm not extremely comfortable with all that is going on in the code here.

[bluesmoon]

Thanks, I know about the extra beacon on unload, and I have a fix for this which I'll push out soon.

The if(!this.unloadfired) is not the problem. That code does the right thing.

[crashbob]

Glad I asked about it first. Any idea how soon it will be pushed? Or do you have a commit number from another fork I could look at?

[bluesmoon]

Just pushed it here. In future you can have a look at my fork at bluesmoon/boomerang which is sometimes about 2 weeks ahead of this one.