Capturing load time stats (#15157)

app/scripts/app-init.js

@@ -1,42 +1,89 @@
+// This file is used only for manifest version 3
+
+// Represents if importAllScripts has been run
+// eslint-disable-next-line
+let scriptsLoaded = false;
+
+// Variable testMode is set to true when preparing test build.
+// This helps in changing service worker execution in test environment.
+const testMode = false;
+
+const loadTimeLogs = [];
+
 // eslint-disable-next-line import/unambiguous
 function tryImport(...fileNames) {
   try {
+    const startTime = new Date().getTime();
     // eslint-disable-next-line
     importScripts(...fileNames);
+    const endTime = new Date().getTime();
+    loadTimeLogs.push({
+      name: fileNames[0],
+      value: endTime - startTime,
+      children: [],
+      startTime,
+      endTime,
+    });
+
     return true;
   } catch (e) {
     console.error(e);
-    return false;
   }
+
+  return false;
 }
 
 function importAllScripts() {
+  // Bail if we've already imported scripts
+  if (scriptsLoaded) {
+    return;
+  }
+
+  const files = [];
+
+  // In testMode individual files are imported, this is to help capture load time stats
+  const loadFile = (fileName) => {
+    if (testMode) {
+      tryImport(fileName);
+    } else {
+      files.push(fileName);
+    }
+  };
+
   const startImportScriptsTime = Date.now();
   // value of applyLavaMoat below is dynamically replaced at build time with actual value
   const applyLavaMoat = true;
 
-  tryImport('./globalthis.js');
-  tryImport('./sentry-install.js');
+  loadFile('./globalthis.js');
+  loadFile('./sentry-install.js');
 
   if (applyLavaMoat) {
-    tryImport('./runtime-lavamoat.js');
-    tryImport('./lockdown-more.js');
-    tryImport('./policy-load.js');
+    loadFile('./runtime-lavamoat.js');
+    loadFile('./lockdown-more.js');
+    loadFile('./policy-load.js');
   } else {
-    tryImport('./init-globals.js');
-    tryImport('./lockdown-install.js');
-    tryImport('./lockdown-run.js');
-    tryImport('./lockdown-more.js');
-    tryImport('./runtime-cjs.js');
+    loadFile('./init-globals.js');
+    loadFile('./lockdown-install.js');
+    loadFile('./lockdown-run.js');
+    loadFile('./lockdown-more.js');
+    loadFile('./runtime-cjs.js');
   }
 
+  // Mark scripts as loaded
+  scriptsLoaded = true;
+
   const fileList = [
     // The list of files is injected at build time by replacing comment below with comma separated strings of file names
     // https://github.com/MetaMask/metamask-extension/blob/496d9d81c3367931031edc11402552690c771acf/development/build/scripts.js#L406
     /** FILE NAMES */
   ];
 
-  fileList.forEach((fileName) => tryImport(fileName));
+  fileList.forEach((fileName) => loadFile(fileName));
+
+  // Import all required resources
+  tryImport(...files);
+
+  const endImportScriptsTime = Date.now();
 
   // for performance metrics/reference
   console.log(
@@ -44,7 +91,34 @@ function importAllScripts() {
       (Date.now() - startImportScriptsTime) / 1000
     }`,
   );
+
+  // In testMode load time logs are output to console
+  if (testMode) {
+    console.log(
+      `Time for each import: ${JSON.stringify(
+        {
+          name: 'Total',
+          children: loadTimeLogs,
+          startTime: startImportScriptsTime,
+          endTime: endImportScriptsTime,
+          value: endImportScriptsTime - startImportScriptsTime,
+          version: 1,
+        },
+        undefined,
+        '    ',
+      )}`,
+    );
+  }
 }
 
-// Placing script import call here ensures that scripts are inported each time service worker is activated.
-importAllScripts();
+// eslint-disable-next-line no-undef
+self.addEventListener('install', importAllScripts);
+
+/*
+ * Message event listener below loads script if they are no longer available.
+ * chrome below needs to be replaced by cross-browser object,
+ * but there is issue in importing webextension-polyfill into service worker.
+ * chrome does seems to work in at-least all chromium based browsers
+ */
+// eslint-disable-next-line no-undef
+chrome.runtime.onMessage.addListener(importAllScripts);

development/build/scripts.js

@@ -375,10 +375,12 @@ const postProcessServiceWorker = (
     const appInitFile = `./dist/${browser}/app-init.js`;
     const fileContent = readFileSync('./app/scripts/app-init.js', 'utf8');
     let fileOutput = fileContent.replace('/** FILE NAMES */', fileList);
-    if (!testing) {
-      // Lavamoat is always set to true in testing mode
+    if (testing) {
+      fileOutput = fileOutput.replace('testMode = false', 'testMode = true');
+    } else {
+      // Setting applyLavaMoat to true in testing mode
       // This is to enable capturing initialisation time stats using e2e with lavamoat statsMode enabled
-      fileOutput = fileContent.replace(
+      fileOutput = fileOutput.replace(
         'const applyLavaMoat = true;',
         `const applyLavaMoat = ${applyLavaMoat};`,
       );
@@ -430,6 +432,8 @@ async function bundleMV3AppInitialiser({
     testing,
   );
 
+  // If the application is running in development mode, we watch service worker file to
+  // in case the file is changes we need to process it again to replace "/** FILE NAMES */", "testMode" etc.
   if (devMode && !testing) {
     let prevChromeFileContent;
     watch('./dist/chrome/app-init.js', () => {
@@ -444,6 +448,8 @@ async function bundleMV3AppInitialiser({
     });
   }
 
+  // Code below is used to set statsMode to true when testing in MV3
+  // This is used to capture module initialisation stats using lavamoat.
   if (testing) {
     const content = readFileSync('./dist/chrome/runtime-lavamoat.js', 'utf8');
     const fileOutput = content.replace('statsMode = false', 'statsMode = true');

package.json

@@ -17,7 +17,7 @@
     "build:dev": "node development/build/index.js",
     "start:test": "SEGMENT_HOST='https://api.segment.io' SEGMENT_WRITE_KEY='FAKE' yarn build testDev",
     "benchmark:chrome": "SELENIUM_BROWSER=chrome node test/e2e/benchmark.js",
-    "mv3:stats:chrome": "SELENIUM_BROWSER=chrome ENABLE_MV3=true node test/e2e/lavamoat-stats.js",
+    "mv3:stats:chrome": "SELENIUM_BROWSER=chrome ENABLE_MV3=true node test/e2e/mv3/stats.js",
     "benchmark:firefox": "SELENIUM_BROWSER=firefox node test/e2e/benchmark.js",
     "build:test": "SEGMENT_HOST='https://api.segment.io' SEGMENT_WRITE_KEY='FAKE' yarn build test",
     "build:test:flask": "yarn build test --build-type flask",

test/e2e/mv3/stats.js

@@ -0,0 +1,142 @@
+#!/usr/bin/env node
+
+/* eslint-disable node/shebang */
+const path = require('path');
+const { promises: fs, constants: fsConstants } = require('fs');
+const yargs = require('yargs/yargs');
+const { hideBin } = require('yargs/helpers');
+const { exitWithError } = require('../../../development/lib/exit-with-error');
+const { withFixtures, tinyDelayMs } = require('../helpers');
+
+async function measurePage() {
+  let metrics;
+  try {
+    await withFixtures({ fixtures: 'imported-account' }, async ({ driver }) => {
+      await driver.delay(tinyDelayMs);
+      await driver.navigate();
+      await driver.findElement('#password');
+      await driver.delay(1000);
+      const logs = await driver.checkBrowserForLavamoatLogs();
+
+      let logString = '';
+      let inObject = false;
+
+      const parsedLogs = [];
+
+      logs.forEach((log) => {
+        if (log.indexOf('"version": 1') >= 0) {
+          logString += log;
+          parsedLogs.push(`{${logString}}`);
+          logString = '';
+          inObject = false;
+        } else if (inObject) {
+          logString += log;
+        } else if (
+          log.search(/"name": ".*app\/scripts\/background.js",/u) >= 0 ||
+          log.search(/"name": ".*app\/scripts\/ui.js",/u) >= 0 ||
+          log.search(/"name": "Total"/u) >= 0
+        ) {
+          logString += log;
+          inObject = true;
+        }
+      });
+
+      metrics = parsedLogs.map((pl) => JSON.parse(pl));
+    });
+  } catch (error) {
+    // do nothing
+  }
+  return metrics;
+}
+
+async function profilePageLoad() {
+  const results = await measurePage();
+  const metrics = {};
+
+  metrics['background.js'] = results[0];
+  metrics['ui.js'] = results[1];
+  metrics.loadTime = results[2];
+
+  return metrics;
+}
+
+async function isWritable(directory) {
+  try {
+    await fs.access(directory, fsConstants.W_OK);
+    return true;
+  } catch (error) {
+    if (error.code !== 'EACCES') {
+      throw error;
+    }
+    return false;
+  }
+}
+
+async function getFirstParentDirectoryThatExists(directory) {
+  let nextDirectory = directory;
+  for (;;) {
+    try {
+      await fs.access(nextDirectory, fsConstants.F_OK);
+      return nextDirectory;
+    } catch (error) {
+      if (error.code !== 'ENOENT') {
+        throw error;
+      } else if (nextDirectory === path.dirname(nextDirectory)) {
+        throw new Error('Failed to find parent directory that exists');
+      }
+      nextDirectory = path.dirname(nextDirectory);
+    }
+  }
+}
+
+async function main() {
+  const { argv } = yargs(hideBin(process.argv)).usage(
+    '$0 [options]',
+    'Run a page load benchmark',
+    (_yargs) =>
+      _yargs.option('out', {
+        description:
+          'Output filename. Output printed to STDOUT of this is omitted.',
+        type: 'string',
+        normalize: true,
+      }),
+  );
+
+  const { out } = argv;
+
+  let outputDirectory;
+  let existingParentDirectory;
+  if (out) {
+    outputDirectory = path.dirname(out);
+    existingParentDirectory = await getFirstParentDirectoryThatExists(
+      outputDirectory,
+    );
+    if (!(await isWritable(existingParentDirectory))) {
+      throw new Error('Specified output file directory is not writable');
+    }
+  }
+
+  const results = await profilePageLoad();
+
+  if (out) {
+    if (outputDirectory !== existingParentDirectory) {
+      await fs.mkdir(outputDirectory, { recursive: true });
+    }
+
+    await fs.writeFile(
+      path.join(out, 'background.json'),
+      JSON.stringify(results['background.js'], null, 2),
+    );
+
+    await fs.writeFile(
+      path.join(out, 'ui.json'),
+      JSON.stringify(results['ui.js'], null, 2),
+    );
+  } else {
+    console.log(JSON.stringify(results, null, 2));
+  }
+}
+
+main().catch((error) => {
+  exitWithError(error);
+});