Merge pull request #5296 from guardian/mxdvl/islands-perf

Performance monitoring: Islands

dotcom-rendering/src/web/browser/initPerf.ts

@@ -1,42 +1,33 @@
-import { log } from '@guardian/libs';
-
+const prefix = 'dotcom.performance';
+
+/**
+ * Helper to measure the duration of any task.
+ *
+ * Values are rounded up to the nearest millisecond,
+ * in order to not under-report any duration.
+ */
 export const initPerf = (
  name: string,
-): { start: () => void; end: () => number; clear: () => void } => {
- type TimeTakenInMilliseconds = number;
-
+): { start: () => number; end: () => number; clear: () => void } => {
  const perf = window.performance;
- const startKey = `${name}-start`;
- const endKey = `${name}-end`;
+ const startKey = `${prefix}.${name}-start`;
+ const endKey = `${prefix}.${name}-end`;
 
- if (!perf || !perf.getEntriesByName) {
- // Return noops if window.performance or the required functions don't exist
- return {
- start: () => {},
- end: () => 0,
- clear: () => {},
- };
+ if (!('mark' in perf)) {
+ return { start: () => 0, end: () => 0, clear: () => {} };
  }
 
+ /** @returns time elapsed since [time origin](https://developer.mozilla.org/en-US/docs/Web/API/DOMHighResTimeStamp#the_time_origin) in milliseconds */
  const start = () => {
- perf.mark(startKey);
+ const { startTime } = perf.mark(startKey);
+ return Math.ceil(startTime);
  };
 
- const end = (): TimeTakenInMilliseconds => {
+ /** @returns length of task in milliseconds */
+ const end = (): number => {
  perf.mark(endKey);
- perf.measure(name, startKey, endKey);
-
- log('dotcom', JSON.stringify(perf.getEntriesByName(name)));
-
- const measureEntries = perf.getEntriesByName(name, 'measure');
- const timeTakenFloat =
- (measureEntries &&
- measureEntries[0] &&
- measureEntries[0].duration) ||
- 0;
- const timeTakenInt = Math.round(timeTakenFloat);
-
- return timeTakenInt;
+ const { duration } = perf.measure(name, startKey, endKey);
+ return Math.ceil(duration);
  };
 
  const clear = () => {

dotcom-rendering/src/web/browser/islands/doHydration.ts

@@ -37,15 +37,31 @@ export const doHydration = (
 
  if (clientOnly) {
  element.querySelector('[data-name="placeholder"]')?.remove();
- log('dotcom', `Rendering island ${name}`);
  render(h(module[name], data), element);
  } else {
- log('dotcom', `Hydrating island ${name}`);
  hydrate(h(module[name], data), element);
  }
 
  element.setAttribute('data-gu-ready', 'true');
- end();
+ const timeTaken = end();
+
+ return { clientOnly, timeTaken };
+ })
+ .then(({ clientOnly, timeTaken }) => {
+ // Log performance info
+ const entry = window.performance
+ .getEntriesByType('resource')
+ .find((p) => p.name.includes(`${name}-importable.`));
+ const { requestStart = 0, responseEnd = 0 } =
+ entry instanceof PerformanceResourceTiming ? entry : {};
+ const download = Math.ceil(responseEnd - requestStart);
+
+ const action = clientOnly ? 'Rendering' : 'Hydrating';
+
+ log(
+ 'dotcom',
+ `🏝 ${action} island <${name} /> took ${timeTaken}ms (downloaded in ${download}ms)`,
+ );
  })
  .catch((error) => {
  if (name && error.message.includes(name)) {

yarn.lock

@@ -2624,9 +2624,9 @@
  "@emotion/memoize" "0.7.4"
 
 "@emotion/jest@^11.3.0":
- version "11.9.1"
- resolved "https://registry.yarnpkg.com/@emotion/jest/-/jest-11.9.1.tgz#65224814552eab6acb923504e597c6f6b67e90d6"
- integrity sha512-JFf9yBA6a7fKrKCWMmjODGRcgBnjiQsl9AakP1y7oRJ6B147ZKPo8DgzHUZ5qQkI06GKAWwYU1vKROInc7SYVA==
+ version "11.9.3"
+ resolved "https://registry.yarnpkg.com/@emotion/jest/-/jest-11.9.3.tgz#24a392d24e9af1f91bd1297ab1e53f069f9ca47c"
+ integrity sha512-fDfZc1ydjjJ+2IDAK+rP+rm469I4u5cIkN3zmGYf0CBW9TLrtM9u9kke3s+i5/M2UpcqLDvtal0EyPBR0A8EWg==
  dependencies:
  "@babel/runtime" "^7.13.10"
  "@emotion/css-prettifier" "^1.0.1"
@@ -12425,7 +12425,7 @@ is-core-module@^2.2.0, is-core-module@^2.5.0:
  dependencies:
  has "^1.0.3"
 
-is-core-module@^2.8.0, is-core-module@^2.8.1:
+is-core-module@^2.8.0, is-core-module@^2.8.1, is-core-module@^2.9.0:
  version "2.9.0"
  resolved "https://registry.yarnpkg.com/is-core-module/-/is-core-module-2.9.0.tgz#e1c34429cd51c6dd9e09e0799e396e27b19a9c69"
  integrity sha512-+5FPy5PnwmO3lvfMb0AsoPaBG+5KHUI0wYFXOtYPnVVVspTFUuMZNfNaNVRt3FZadstu2c8x23vykRW/NBoU6A==
@@ -17210,9 +17210,9 @@ react-is@17.0.2, react-is@^17.0.1, react-is@^17.0.2:
  integrity sha512-w2GsyukL62IJnlaff/nRegPQR94C/XXamvMWmSHRJ4y7Ts/4ocGRmTHvOs8PSE6pB3dWOrD/nueuU5sduBsQ4w==
 
 "react-is@^16.12.0 || ^17.0.0 || ^18.0.0":
- version "18.1.0"
- resolved "https://registry.yarnpkg.com/react-is/-/react-is-18.1.0.tgz#61aaed3096d30eacf2a2127118b5b41387d32a67"
- integrity sha512-Fl7FuabXsJnV5Q1qIOQwx/sagGF18kogb4gpfcG4gjLBWO0WDiiz1ko/ExayuxE7InyQkBLkxRFG5oxY6Uu3Kg==
+ version "18.2.0"
+ resolved "https://registry.yarnpkg.com/react-is/-/react-is-18.2.0.tgz#199431eeaaa2e09f86427efbb4f1473edb47609b"
+ integrity sha512-xWGDIW6x921xtzPkhiULtthJHoJvBbF3q26fzloPCK0hsvxtPVelvftw3zjbHWSkR2km9Z+4uxbDDK/6Zw9B8w==
 
 react-is@^16.13.1, react-is@^16.7.0, react-is@^16.8.1, react-is@^16.8.4:
  version "16.13.1"
@@ -17897,7 +17897,16 @@ resolve@1.x, resolve@^1.10.0, resolve@^1.12.0, resolve@^1.13.1, resolve@^1.14.2,
  is-core-module "^2.2.0"
  path-parse "^1.0.6"
 
-resolve@^1.18.1, resolve@^1.22.0:
+resolve@^1.18.1:
+ version "1.22.1"
+ resolved "https://registry.yarnpkg.com/resolve/-/resolve-1.22.1.tgz#27cb2ebb53f91abb49470a928bba7558066ac177"
+ integrity sha512-nBpuuYuY5jFsli/JIs1oldw6fOQCBioohqWZg/2hiaOybXOft4lonv85uDOKXdf8rhyK159cxU5cDcK/NKk8zw==
+ dependencies:
+ is-core-module "^2.9.0"
+ path-parse "^1.0.7"
+ supports-preserve-symlinks-flag "^1.0.0"
+
+resolve@^1.22.0:
  version "1.22.0"
  resolved "https://registry.yarnpkg.com/resolve/-/resolve-1.22.0.tgz#5e0b8c67c15df57a89bdbabe603a002f21731198"
  integrity sha512-Hhtrw0nLeSrFQ7phPp4OOcVjLPIeMnRlr5mcnVuMe7M/7eBn98A3hmFRLoFo3DLZkivSYwhRUJTyPyWAk56WLw==