PERF-813 Capture diagnostic details (#63)

* Assert expected diagnostic detail

* Capture and report diagnostic details

* fix: ?? operator is lower precedence than >= !

* Consolidate diagnostic detail in `lastVisualUpdate` key

* lastVisualUpdate -> lastVisibleChange

* Document new diagnostic detail in README

Co-authored-by: Andrew Hyndman <ahyndman@dropbox.com>

README.md

@@ -187,6 +187,11 @@ export type Metric = {
   detail: {
     // if ttvc ignored a stalled network request, this value will be true
     didNetworkTimeOut: boolean;
+
+    // the most recent visible update
+    // (this can be either a mutation or a load event target, whichever
+    // occurred last)
+    lastVisibleChange?: HTMLElement | TimestampedMutationRecord;
   };
 };
 ```

src/inViewportImageObserver.ts

@@ -21,11 +21,11 @@ import {Logger} from './util/logger';
 export class InViewportImageObserver {
   private intersectionObserver: IntersectionObserver;
   private imageLoadTimes = new Map<HTMLImageElement | HTMLIFrameElement, number>();
-  private callback: (timestamp: number) => void;
+  private callback: (timestamp: number, img: HTMLImageElement | HTMLIFrameElement) => void;
 
   public lastImageLoadTimestamp = 0;
 
-  constructor(callback: (timestamp: number) => void) {
+  constructor(callback: (timestamp: number, img: HTMLElement) => void) {
     this.callback = callback;
     this.intersectionObserver = new IntersectionObserver(this.intersectionObserverCallback);
   }
@@ -36,7 +36,7 @@ export class InViewportImageObserver {
       const timestamp = this.imageLoadTimes.get(img);
       if (entry.isIntersecting && timestamp != null) {
         Logger.info('InViewportImageObserver.callback()', '::', 'timestamp =', timestamp);
-        this.callback(timestamp);
+        this.callback(timestamp, img);
       }
       this.intersectionObserver.unobserve(img);
       this.imageLoadTimes.delete(img);

src/visuallyCompleteCalculator.ts

@@ -1,4 +1,4 @@
-import {InViewportMutationObserver} from './inViewportMutationObserver';
+import {InViewportMutationObserver, TimestampedMutationRecord} from './inViewportMutationObserver';
 import {waitForPageLoad} from './util';
 import {requestAllIdleCallback} from './requestAllIdleCallback';
 import {InViewportImageObserver} from './inViewportImageObserver';
@@ -19,6 +19,9 @@ export type Metric = {
   detail: {
     // if ttvc ignored a stalled network request, this value will be true
     didNetworkTimeOut: boolean;
+
+    // the most recent visual update; this can be either a mutation or a load event target
+    lastVisibleChange?: HTMLElement | TimestampedMutationRecord;
   };
 };
 
@@ -35,8 +38,9 @@ class VisuallyCompleteCalculator {
   private inViewportImageObserver: InViewportImageObserver;
 
   // measurement state
-  private lastMutationTimestamp = 0;
-  private lastImageLoadTimestamp = 0;
+  private lastMutation?: TimestampedMutationRecord;
+  private lastImageLoadTimestamp = -1;
+  private lastImageLoadTarget?: HTMLElement;
   private subscribers = new Set<MetricSubscriber>();
   private navigationCount = 0;
 
@@ -58,14 +62,17 @@ class VisuallyCompleteCalculator {
       throw new Error('VisuallyCompleteCalculator: This browser/runtime is not supported.');
     }
 
-    this.inViewportMutationObserver = new InViewportMutationObserver(
-      (mutation) =>
-        (this.lastMutationTimestamp = Math.max(this.lastMutationTimestamp, mutation.timestamp ?? 0))
-    );
-    this.inViewportImageObserver = new InViewportImageObserver(
-      (timestamp) =>
-        (this.lastImageLoadTimestamp = Math.max(this.lastImageLoadTimestamp, timestamp))
-    );
+    this.inViewportMutationObserver = new InViewportMutationObserver((mutation) => {
+      if ((mutation.timestamp ?? 0) >= (this.lastMutation?.timestamp ?? 0)) {
+        this.lastMutation = mutation;
+      }
+    });
+    this.inViewportImageObserver = new InViewportImageObserver((timestamp, img) => {
+      if (timestamp >= this.lastImageLoadTimestamp) {
+        this.lastImageLoadTimestamp = timestamp;
+        this.lastImageLoadTarget = img;
+      }
+    });
   }
 
   /** begin measuring a new navigation */
@@ -100,14 +107,20 @@ class VisuallyCompleteCalculator {
 
     if (!shouldCancel) {
       // identify timestamp of last visible change
-      const end = Math.max(start, this.lastImageLoadTimestamp, this.lastMutationTimestamp);
+      const end = Math.max(start, this.lastImageLoadTimestamp, this.lastMutation?.timestamp ?? 0);
 
       // report result to subscribers
       this.next({
         start,
         end,
         duration: end - start,
-        detail: {didNetworkTimeOut},
+        detail: {
+          didNetworkTimeOut,
+          lastVisibleChange:
+            this.lastImageLoadTimestamp > (this.lastMutation?.timestamp ?? 0)
+              ? this.lastImageLoadTarget
+              : this.lastMutation,
+        },
       });
     }
 
@@ -141,7 +154,7 @@ class VisuallyCompleteCalculator {
       'lastImageLoadTimestamp =',
       this.lastImageLoadTimestamp,
       'lastMutationTimestamp =',
-      this.lastMutationTimestamp
+      this.lastMutation?.timestamp ?? 0
     );
     Logger.info('TTVC:', measurement);
     this.subscribers.forEach((subscriber) => subscriber(measurement));

test/e2e/output1/index.html

@@ -0,0 +1,9 @@
+<head>
+  <script src="/dist/index.min.js"></script>
+  <script src="/analytics.js"></script>
+</head>
+
+<body>
+  <h1 id="h1">Hello world!</h1>
+  <img src="/150.png?delay=500" />
+</body>

test/e2e/output1/index.spec.ts

@@ -0,0 +1,39 @@
+import {test, expect} from '@playwright/test';
+
+import {FUDGE} from '../../util/constants';
+import {getEntries} from '../../util/entries';
+
+const PAGELOAD_DELAY = 200;
+const IMAGE_DELAY = 500;
+
+test.describe('TTVC', () => {
+  test('output reports timing data', async ({page}) => {
+    await page.goto(`/test/output1?delay=${PAGELOAD_DELAY}`, {
+      waitUntil: 'networkidle',
+    });
+
+    const entries = await getEntries(page);
+
+    expect(entries.length).toBe(1);
+    expect(entries[0].duration).toBeGreaterThanOrEqual(PAGELOAD_DELAY + IMAGE_DELAY);
+    expect(entries[0].duration).toBeLessThanOrEqual(PAGELOAD_DELAY + IMAGE_DELAY + FUDGE);
+    expect(entries[0].start).toBeDefined();
+    expect(entries[0].end).toBeDefined();
+  });
+
+  test('output includes detail', async ({page}) => {
+    await page.goto(`/test/output1?delay=${PAGELOAD_DELAY}`, {
+      waitUntil: 'networkidle',
+    });
+
+    const entries = await getEntries(page);
+
+    expect(entries.length).toBe(1);
+    expect(entries[0].detail).toBeDefined();
+    expect(entries[0].detail.didNetworkTimeOut).toBe(false);
+    const isImageElement = await page.evaluate(() => {
+      return window.entries[0].detail.lastVisibleChange instanceof HTMLImageElement;
+    });
+    expect(isImageElement).toBe(true);
+  });
+});

test/e2e/output2/index.html

@@ -0,0 +1,8 @@
+<head>
+  <script src="/dist/index.min.js"></script>
+  <script src="/analytics.js"></script>
+</head>
+
+<body>
+  <h1 id="h1">Hello world!</h1>
+</body>

test/e2e/output2/index.spec.ts

@@ -0,0 +1,39 @@
+import {test, expect} from '@playwright/test';
+
+import {FUDGE} from '../../util/constants';
+import {getEntries} from '../../util/entries';
+
+const PAGELOAD_DELAY = 200;
+
+test.describe('TTVC', () => {
+  test('output reports timing data', async ({page}) => {
+    await page.goto(`/test/output2?delay=${PAGELOAD_DELAY}`, {
+      waitUntil: 'networkidle',
+    });
+
+    const entries = await getEntries(page);
+
+    expect(entries.length).toBe(1);
+    expect(entries[0].duration).toBeGreaterThanOrEqual(PAGELOAD_DELAY);
+    expect(entries[0].duration).toBeLessThanOrEqual(PAGELOAD_DELAY + FUDGE);
+    expect(entries[0].start).toBeDefined();
+    expect(entries[0].end).toBeDefined();
+  });
+
+  test('output includes detail', async ({page}) => {
+    await page.goto(`/test/output2?delay=${PAGELOAD_DELAY}`, {
+      waitUntil: 'networkidle',
+    });
+
+    const entries = await getEntries(page);
+
+    expect(entries.length).toBe(1);
+    expect(entries[0].detail).toBeDefined();
+    expect(entries[0].detail.didNetworkTimeOut).toBe(false);
+
+    const isMutationRecord = await page.evaluate(() => {
+      return window.entries[0].detail.lastVisibleChange instanceof MutationRecord;
+    });
+    expect(isMutationRecord).toBe(true);
+  });
+});