StopWatch and custom metrics associated with wrong URL-or-alias

jordan-angold-sophos commented 1 year ago

Have you read the documentation?

[X] Yes, I've read the how to make a reproducable bug guide
[X] Yes, I've read the how to debug my script guide

URL

What are you trying to accomplish

I'm testing an SPA and trying to record several test cases, each of which has custom timers using a stopwatch. I am trying to automate extracting those custom timers from JSON data retrieved using the analysisstorer plugin.

What browser did you use?

Chrome

How to reproduce

Run these two test scripts in sequence, in a single docker run command.
bug_first.js:
module.exports = async function (context, commands) {
  try {
    await commands.navigate("https://sitespeed.io");
    await commands.measure.start("first_test");
    const stopWatch = commands.stopWatch.get('first_stopwatch');
    // some interesting operation here
    const stopWatchTime = stopWatch.stopAndAdd();
    return commands.measure.stop();
  } catch (e) {
    context.log.error(e);
    throw e;
  }
}

bug_second.js:
module.exports = async function (context, commands) {
  try {
    await commands.navigate("https://google.com");
    await commands.measure.start("second_test");
    const stopWatch = commands.stopWatch.get('second_stopwatch');
    // some interesting operation here
    const stopWatchTime = stopWatch.stopAndAdd();
    return commands.measure.stop();
  } catch (e) {
    context.log.error(e);
    throw e;
  }
}

Log output

[2023-08-18 20:32:27] INFO: [sitespeedio] Versions OS: linux 6.1.30-0-virt nodejs: v18.16.0 sitespeed.io: 29.3.0 browsertime: 17.15.0 coach: 7.2.1
[2023-08-18 20:32:27] INFO: [browsertime] Running tests using Chrome - 1 iteration(s)
[2023-08-18 20:32:28] INFO: [browsertime.command.measure] Navigating to url https://sitespeed.io iteration 1
[2023-08-18 20:32:34] INFO: [browsertime.command.measure] Start to measure first_test
[2023-08-18 20:32:35] ERROR: [browsertime.command.measure] You need to have done one (start/stop) measurement before you can add any metrics to a result.
[2023-08-18 20:32:36] INFO: [browsertime.command.measure] Take after page complete check screenshot
[2023-08-18 20:32:37] INFO: [browsertime.command.measure] Take cumulative layout shift screenshot
[2023-08-18 20:32:37] INFO: [browsertime.command.measure] Take largest contentful paint screenshot
[2023-08-18 20:32:38] INFO: [browsertime.command.measure] Navigating to url https://google.com iteration 1
[2023-08-18 20:32:44] INFO: [browsertime.command.measure] Start to measure second_test
[2023-08-18 20:32:46] INFO: [browsertime.command.measure] Take after page complete check screenshot
[2023-08-18 20:32:46] INFO: [browsertime.command.measure] Take cumulative layout shift screenshot
[2023-08-18 20:32:47] INFO: [browsertime.command.measure] Take largest contentful paint screenshot
[2023-08-18 20:32:50] INFO: [browsertime.video] Use the visual metrics portable script
[2023-08-18 20:32:50] INFO: [browsertime.video] Get visual metrics from the video
[2023-08-18 20:32:50] INFO: [browsertime.video] Use the visual metrics portable script
[2023-08-18 20:32:50] INFO: [browsertime.video] Get visual metrics from the video
[2023-08-18 20:32:51] ERROR: [browsertime] Could not add meta data to the HAR, miss page 0
[2023-08-18 20:32:51] ERROR: [browsertime] Could not add meta data to the HAR, miss page 1
[2023-08-18 20:32:51] INFO: [browsertime] https://www.sitespeed.io/ TTFB: 491ms, firstPaint: 633ms, firstVisualChange: 0ms, FCP: 633ms, DOMContentLoaded: 711ms, LCP: 685ms, CLS: 0.0004, TBT: 0ms, CPUBenchmark: 50ms, Load: 727ms, speedIndex: 0ms, visualComplete85: 0ms, lastVisualChange: 0ms
[2023-08-18 20:32:51] INFO: [browsertime] https://www.google.com/ TTFB: 457ms, firstPaint: 562ms, firstVisualChange: 0ms, FCP: 562ms, DOMContentLoaded: 673ms, LCP: 621ms, CLS: 0, TBT: 0ms, CPUBenchmark: 58ms, Load: 1.20s, speedIndex: 0ms, visualComplete85: 0ms, lastVisualChange: 0ms
[2023-08-18 20:32:51] ERROR: [plugin.browsertime] Could not find the right index 0 for har for url https://www.sitespeed.io/ 
[2023-08-18 20:32:51] ERROR: [plugin.browsertime] Couldnt get the right page for the HAR Error: PageIndex out of range
    at module.exports.pickAPage (/usr/src/app/node_modules/coach-core/lib/har/harCutter.js:18:11)
    at pickAPage (/usr/src/app/node_modules/coach-core/lib/index.js:84:12)
    at BrowsertimePlugin.processMessage (file:///usr/src/app/lib/plugins/browsertime/index.js:271:29)
[2023-08-18 20:32:51] ERROR: [plugin.browsertime] Caught error from Browsertime Error: PageIndex out of range
    at module.exports.pickAPage (/usr/src/app/node_modules/coach-core/lib/har/harCutter.js:18:11)
    at pickAPage (/usr/src/app/node_modules/coach-core/lib/index.js:84:12)
    at BrowsertimePlugin.processMessage (file:///usr/src/app/lib/plugins/browsertime/index.js:493:33)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[2023-08-18 20:32:51] INFO: [sitespeedio.plugin.html] HTML stored in /sitespeed.io/sitespeed-test-results/20230818/Bug/163225

jordan-angold-sophos commented 1 year ago

Note that the log shows a hint:

[2023-08-18 20:32:35] ERROR: [browsertime.command.measure] You need to have done one (start/stop) measurement before you can add any metrics to a result.

This error seems to be in reference to first_stopwatch.

The first_stopwatch metric is not recorded in any output json files. The second_stopwatch metric incorrectly appears in the output json files for https://google.com, the URL used in first_test.

I think this is due to https://github.com/sitespeedio/browsertime/blob/main/lib/core/engine/command/measure.js#L327 . When adding a metric, the index used is this.numberOfMeasuredPages - 1, but start() and stop() index at this.numberOfMeasuredPages.

The doc language on StopWatch.stopAndAdd() says that the measurement will be added to the "last measured page", which suggests that this could conceivably be intentional behaviour -- but if it is, then it makes stopwatches awkward to use.

soulgalore commented 10 months ago

The stop watch is always registered to the last measured URL, so to make it work you need to adjust the script to first measure that first page load and then do the stop watch thing.

jordan-angold-sophos commented 10 months ago

Are you saying that the correct version of the script is not:

await commands.navigate("https://sitespeed.io");
await commands.measure.start("first_test");
const stopWatch = commands.stopWatch.get('first_stopwatch');
// some interesting operation here
const stopWatchTime = stopWatch.stopAndAdd();
return commands.measure.stop();

but instead:

await commands.navigate("https://sitespeed.io");
await commands.measure.start("first_test");
const stopWatch = commands.stopWatch.get('first_stopwatch');
// some interesting operation here
const stopWatchTime = stopWatch.stop();
await commands.measure.stop();
await commands.measure.add(stopWatch.name, stopWatchTime);

because that makes StopWatch.stopAndAdd() fairly worthless, and makes the whole test more verbose and awkward to write.

sitespeedio / browsertime