akamai / boomerang

End user oriented web performance testing and beaconing
http://akamai.github.io/boomerang/
Other
1.86k stars 292 forks source link

t_done,t_page and rt.tt values are negative on SPA #339

Open annitsb opened 1 year ago

annitsb commented 1 year ago

Hi Team,

Recently we have found an issue in one of the SPA application where t_done is negative. I did analysis around and i found on page scroll SPA beacon is fired and rt.end value is less than rt.start value. I am using auto-xhr, history and spa plugins. Below is the beacon

rt.start: manual rt.tstart: 1669688701496 rt.nstart: 1669688573336 rt.bstart: 1669688575259 rt.end: 1669688700932 t_resp: 0 t_page: -564 t_done: -564 rt.tt: -3742

querymetrics commented 1 year ago

Hi @annitsb , do you have a public site that you could share that reproduces the issue?

Boomerang SPA monitoring doesn't capture scroll events. Could you describe the workflow that happens when a scroll occurs? History API calls, XHRs, etc.

annitsb commented 1 year ago

Hi QueryMetrics,

We don't have site which is public, it is internal application. When i do slow scroll i dont see negative value but when i do scrolling fast, i am able to reproduce negative values for t_done, t_page, rt.tt

bluesmoon commented 1 year ago

@annitsb do you have your own scroll handler that fires XHRs or something else when scrolls happen? Boomerang itself doesn't look at scrolling so something else is firing network transitions. If your site is doing something during scroll, it may be useful to implement some kind of throttling or debouncing for the scroll event.

See https://css-tricks.com/debouncing-throttling-explained-examples/ for some information.

annitsb commented 1 year ago

On scroll, whenever switched to different tab, we have this code in application history.replaceState

bluesmoon commented 1 year ago

@annitsb please include the code that you mention.

annitsb commented 1 year ago

angular SPA application have below java script function , this function will be called on SCROLL on page.

addAnchorToUrl(t) {
                    let a = window.location.href.split("#")[0] + "#!" + t;
                    history.replaceState(null, null, a),
                    this.anchor = t
                }

And in boomerang i can see below code in History.js plugin

if (impl.monitorReplaceState && typeof history.replaceState === "function") {
            history.replaceState = (function(_replaceState) {
                return function(state, title, url) {
                    var fromUrl = BOOMR.window.document.URL, toUrl = fromUrl;

As i said initially i see negative value only when i scroll page fast, if i scroll page slowly and give some pause, then i get correct data.

bluesmoon commented 1 year ago

Will look into why this is happening, but just FYI, there is a bug in your code. Using location.href doesn't work well for # across browsers as Safari will URL encode it. You should use document.URL instead.

annitsb commented 1 year ago

we are currently checking for Chrome and Edge. Issue is more frequently reproducible in Chrome

annitsb commented 1 year ago

Hi bluesmoon, Any update on this?

bluesmoon commented 1 year ago

No, I don't see anything in the code that would cause the values to be negative.

annitsb commented 1 year ago

Ok, so what will happen if user set history.replacestate. how beacon fired?. and please help me in understanding how rt.tstart and rt.end values are assigned? because i see rt.end is less than rt.tstart. and t_done = rt.end-rt.tstart which gives negative value. i am curious to know how rt.end can be less than rt.tstart

bluesmoon commented 1 year ago

when you call history.replaceState or history.pushState, it calls a function in the history.js plugin. This in turn fires a route_change in the spa.js plugin. This sets the start time, and then sets a mutation observer to watch for changes to the DOM or network events (auto-xhr.js). Once everything is stable, it fires a sendResource which calculates the end time. Throughout this process, the object with the start time is passed through from call to call, so the end time should always be >= the start time. I can't tell why it's not just by inspecting the code.

annitsb commented 1 year ago

Thank you bluesmoon. I will do some analysis around application and check end time is less than start time.

querymetrics commented 1 year ago

Can you run a debug version of boomerang and post the console logs when you see a negative timer?

annitsb commented 1 year ago

how to run debug version of boomerang

ceckoslab commented 1 year ago

Hello @annitsb

The build process automatically creates a debug build.

After you build Boomerang, then could you check the build folder for file that end with -debug.js?

You should have something similar to:

Screen Shot 2022-12-07 at 9 47 52 AM

annitsb commented 1 year ago

Hi ceckoslab,

Please find console logs console_logs.txt

ceckoslab commented 1 year ago

@annitsb very interesting ... your boomerang is called boomerang-history.min.js.

I see some debug info but I am not sure that this is really a debug build because I would expect the log to be much more verbose.

Could you please share unminified debug version from your boomerang?

annitsb commented 1 year ago

Please find attachment. It was not allowing to attach javascript, so i changes ext to txt boomerang.txt

annitsb commented 1 year ago

any update on this issue?

ceckoslab commented 1 year ago

Hello again @annitsb

I looked at the share log and the Boomerang build but I still can't find why this could be happening.

The log that you shared previously seems to be filtered. Could you send a full log only with Boomerang messages?

Also is it possible to share the code where you call BOOMR.init in your application?