sitespeed.io icon indicating copy to clipboard operation
sitespeed.io copied to clipboard
verified publisher icon sitespeedio

CPU measurements seem not to reset between measurements (scripting)

Open jannekalliola opened this issue 1 year ago • 3 comments

Have you read the documentation?

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

jannekalliola avatar Dec 01 '24 13:12 jannekalliola

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 avatar Dec 02 '24 06:12 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.

soulgalore avatar Dec 03 '24 04:12 soulgalore

It seems like https://github.com/sitespeedio/browsertime/pull/2220 also fixed this issue. Specifically this commit: https://github.com/sitespeedio/browsertime/pull/2220/commits/9504fc78a13f9e8f6095f6fc6d44af752154d8ff

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 https://github.com/sitespeedio/browsertime/commit/9504fc78a13f9e8f6095f6fc6d44af752154d8ff.

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 https://github.com/sitespeedio/browsertime/pull/2220

canova avatar Dec 09 '24 21:12 canova