CPU measurements seem not to reset between measurements (scripting)

[jannekalliola]

Have you read the documentation?

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

URL

https://www.builder.io/

What are you trying to accomplish

I'm trying to measure CPU power consumption of non-cached and cached pages. When I run the measurement three times (first non-cached and then twice cached), the CPU numbers are as follows:

0.0035 µWh
0.005 µWh
0.0057 µWh

The values are constantly rising, while the two latter runs are identical (and should be less heavy compared to the first one)

What browser did you use?

Firefox

How to reproduce

sitespeed.io -b firefox -n 1 --firefox.geckoProfiler --firefox.geckoProfilerParams.features "power" --firefox.powerConsumption builder-qwik.mjs --multi 

builder-qwik.mjs:

/**
 * @param {import('browsertime').BrowsertimeContext} context
 * @param {import('browsertime').BrowsertimeCommands} commands
 */
export default async function (context, commands) {
  const delayTime = 500;
 
  await commands.measure.start('Non-cached');
  await commands.navigate('https://www.builder.io/');
  try {
    await commands.click.byId('onetrust-accept-btn-handler');
  }
  catch(e) {
  }
  await commands.scroll.byPages(1);
  await commands.wait.byTime(delayTime);
  await commands.scroll.byPages(1);
  await commands.wait.byTime(delayTime);
  await commands.scroll.toBottom(delayTime);
  await commands.measure.stop();
  
  await commands.measure.start('Cached');
  await commands.navigate('https://www.builder.io/');
  try {
    await commands.click.byId('onetrust-accept-btn-handler');
  }
  catch(e) {
  }
  await commands.scroll.byPages(1);
  await commands.wait.byTime(delayTime);
  await commands.scroll.byPages(1);
  await commands.wait.byTime(delayTime);
  await commands.scroll.toBottom(delayTime);
  await commands.measure.stop();
  
  await commands.measure.start('Cached 2');
  await commands.navigate('https://www.builder.io/');
  try {
    await commands.click.byId('onetrust-accept-btn-handler');
  }
  catch(e) {
  }
  await commands.scroll.byPages(1);
  await commands.wait.byTime(delayTime);
  await commands.scroll.byPages(1);
  await commands.wait.byTime(delayTime);
  await commands.scroll.toBottom(delayTime);
  return commands.measure.stop();
};

Log output

[2024-12-01 15:18:54] INFO: Versions OS: darwin 23.6.0 nodejs: v20.11.0 sitespeed.io: 35.6.1 browsertime: 23.4.1 coach: 8.0.2
[2024-12-01 15:18:55] INFO: Running tests using Firefox - 1 iteration(s)
[2024-12-01 15:18:56] INFO: Start to measure Non-cached
[2024-12-01 15:18:56] INFO: Start GeckoProfiler with features: ["power"] and threads: ["GeckoMain","Compositor","Renderer"]
[2024-12-01 15:18:59] INFO: Navigating to url https://www.builder.io/ iteration 1
[2024-12-01 15:19:15] INFO: Collecting Gecko profile from /Users/plastic/Code/phd/sitespeed/sitespeed-result/builder-qwik_mjs/2024-12-01-15-18-54/pages/www_builder_io/Non-cached/data/geckoProfile-1.json to /Users/plastic/Code/phd/sitespeed/sitespeed-result/builder-qwik_mjs/2024-12-01-15-18-54/pages/www_builder_io/Non-cached/data/geckoProfile-1.json
[2024-12-01 15:19:15] INFO: Stop GeckoProfiler.
[2024-12-01 15:19:15] INFO: Collecting CPU power consumtion
[2024-12-01 15:19:15] INFO: Gzip file the profile.
[2024-12-01 15:19:15] INFO: Done stopping GeckoProfiler.
[2024-12-01 15:19:15] INFO: CPU / Power usage: 8408
[2024-12-01 15:19:15] INFO: Take after page complete check screenshot
[2024-12-01 15:19:16] INFO: Take largest contentful paint screenshot
[2024-12-01 15:19:16] INFO: Start to measure Cached
[2024-12-01 15:19:16] INFO: Start GeckoProfiler with features: ["power"] and threads: ["GeckoMain","Compositor","Renderer"]
[2024-12-01 15:19:19] INFO: Navigating to url https://www.builder.io/ iteration 1
[2024-12-01 15:19:25] ERROR: Couldn't execute script named CUSTOM error:JavascriptError: TypeError: document.getElementById(...) is null
[2024-12-01 15:19:25] ERROR: Could not find element by id onetrust-accept-btn-handler
[2024-12-01 15:19:34] INFO: https://www.builder.io/ has been tested before within the same run, it will get an extra query parameter named browsertime_run. Make sure to use alias to keep track of the URLs
[2024-12-01 15:19:34] INFO: Collecting Gecko profile from /Users/plastic/Code/phd/sitespeed/sitespeed-result/builder-qwik_mjs/2024-12-01-15-18-54/pages/www_builder_io/Cached/data/geckoProfile-1.json to /Users/plastic/Code/phd/sitespeed/sitespeed-result/builder-qwik_mjs/2024-12-01-15-18-54/pages/www_builder_io/Cached/data/geckoProfile-1.json
[2024-12-01 15:19:34] INFO: Stop GeckoProfiler.
[2024-12-01 15:19:34] INFO: Collecting CPU power consumtion
[2024-12-01 15:19:34] INFO: Gzip file the profile.
[2024-12-01 15:19:35] INFO: Done stopping GeckoProfiler.
[2024-12-01 15:19:35] INFO: CPU / Power usage: 8189
[2024-12-01 15:19:35] INFO: Take after page complete check screenshot
[2024-12-01 15:19:35] INFO: Take largest contentful paint screenshot
[2024-12-01 15:19:35] INFO: Start to measure Cached 2
[2024-12-01 15:19:35] INFO: Start GeckoProfiler with features: ["power"] and threads: ["GeckoMain","Compositor","Renderer"]
[2024-12-01 15:19:38] INFO: Navigating to url https://www.builder.io/ iteration 1
[2024-12-01 15:19:45] ERROR: Couldn't execute script named CUSTOM error:JavascriptError: TypeError: document.getElementById(...) is null
[2024-12-01 15:19:45] ERROR: Could not find element by id onetrust-accept-btn-handler
[2024-12-01 15:19:54] INFO: https://www.builder.io/ has been tested before within the same run, it will get an extra query parameter named browsertime_run. Make sure to use alias to keep track of the URLs
[2024-12-01 15:19:54] INFO: Collecting Gecko profile from /Users/plastic/Code/phd/sitespeed/sitespeed-result/builder-qwik_mjs/2024-12-01-15-18-54/pages/www_builder_io/Cached-2/data/geckoProfile-1.json to /Users/plastic/Code/phd/sitespeed/sitespeed-result/builder-qwik_mjs/2024-12-01-15-18-54/pages/www_builder_io/Cached-2/data/geckoProfile-1.json
[2024-12-01 15:19:54] INFO: Stop GeckoProfiler.
[2024-12-01 15:19:54] INFO: Collecting CPU power consumtion
[2024-12-01 15:19:54] INFO: Gzip file the profile.
[2024-12-01 15:19:54] INFO: Done stopping GeckoProfiler.
[2024-12-01 15:19:54] INFO: CPU / Power usage: 9604
[2024-12-01 15:19:54] INFO: Take after page complete check screenshot
[2024-12-01 15:19:54] INFO: Take largest contentful paint screenshot
[2024-12-01 15:19:57] INFO: https://www.builder.io/ 175 requests, TTFB: 76ms, firstPaint: 284ms, FCP: 284ms, DOMContentLoaded: 280ms, LCP: 279ms, CPUBenchmark: 25ms, Load: 856ms
[2024-12-01 15:19:57] INFO: https://www.builder.io/?browsertime_run=2 145 requests, TTFB: 17ms, firstPaint: 51ms, FCP: 50ms, DOMContentLoaded: 42ms, LCP: 49ms, CPUBenchmark: 25ms, Load: 239ms
[2024-12-01 15:19:57] INFO: https://www.builder.io/?browsertime_run=3 64 requests, TTFB: 27ms, firstPaint: 66ms, FCP: 67ms, DOMContentLoaded: 56ms, LCP: 55ms, CPUBenchmark: 25ms, Load: 259ms
[2024-12-01 15:19:57] INFO: The server responded with a 500 status code for https://www.builder.io/logan-test
[2024-12-01 15:19:57] INFO: The server responded with a 500 status code for https://www.builder.io/logan-test
[2024-12-01 15:19:57] INFO: The server responded with a 500 status code for https://www.builder.io/logan-test
[2024-12-01 15:19:57] INFO: The server responded with a 500 status code for https://www.builder.io/logan-test
[2024-12-01 15:19:57] INFO: The server responded with a 500 status code for https://www.builder.io/logan-test
[2024-12-01 15:19:57] INFO: The server responded with a 500 status code for https://www.builder.io/logan-test
[2024-12-01 15:19:58] INFO: HTML stored in /Users/plastic/Code/phd/sitespeed/sitespeed-result/builder-qwik_mjs/2024-12-01-15-18-54

[soulgalore]

Hi @jannekalliola thank you for creating the issue. I'll get back tomorrow Tuesday when I have the time to check what's going on.

[soulgalore]

Hi @jannekalliola I could verify the same. I checked the code and it seems correct in Browsertime (we parse the gecko driver log after each time we stop the test to get the metric). I think the root problem is in Firefox or maybe we do something wrong with the trace. I'll create an issue for Firefox later today.

[canova]

It seems like sitespeedio/browsertime#2220 also fixed this issue. Specifically this commit: sitespeedio/browsertime@9504fc7

Adding the same context here:

First values in the counter samples have different meanings per platform. I'm assuming you have macOS with Apple Silicon chips, because this is the behavior I encountered while I was testing too.

It seems like when we call the macOS API for getting the power usage values for the first time, it's returning a very high number, which @fqueze suspected that it's the power value since the process start time. This explains why we are seeing increasing amount of values in the sitespeed.io power metrics. It's because it's never being reset, so it's always include the power usage numbers since the process has started.

To fix this, we simply ignore the initial values now in sitespeedio/browsertime@9504fc7.

I tested with that PR applied on sitespeed.io and it seems like we are now getting expected values, like:
0.0036 µWh
0.0019 µWh
0.0020 µWh

So I think we can close this after sitespeedio/browsertime#2220