Merge branch 'config-and-debug' into dev

src/inViewportImageObserver.ts

@@ -1,3 +1,5 @@
+import {Logger} from './util/logger';
+
 /**
  * Modeled after IntersectionObserver and MutationObserver, this Image observer
  * reports image load times for images that are visible within the viewport.
@@ -30,7 +32,9 @@ export class InViewportImageObserver {
     entries.forEach((entry) => {
       const img = entry.target as HTMLImageElement;
       if (entry.isIntersecting) {
-        this.callback(this.imageLoadTimes.get(img));
+        const timestamp = this.imageLoadTimes.get(img);
+        Logger.info('InViewportImageObserver.callback()', '::', 'timestamp =', timestamp);
+        this.callback(timestamp);
       }
       this.intersectionObserver.unobserve(img);
       this.imageLoadTimes.delete(img);
@@ -39,19 +43,22 @@ export class InViewportImageObserver {
 
   private handleLoadOrErrorEvent = (event: Event) => {
     if (event.target instanceof HTMLImageElement) {
-      this.imageLoadTimes.set(event.target, performance.now());
+      Logger.debug('InViewportImageObserver.handleLoadOrErrorEvent()', '::', 'event =', event);
+      this.imageLoadTimes.set(event.target, event.timeStamp);
       this.intersectionObserver.observe(event.target);
     }
   };
 
   /** Start observing loading images. */
   observe() {
+    Logger.info('InViewportImageObserver.observe()');
     document.addEventListener('load', this.handleLoadOrErrorEvent, {capture: true});
     document.addEventListener('error', this.handleLoadOrErrorEvent, {capture: true});
   }
 
   /** Stop observing loading images, and clean up. */
   disconnect() {
+    Logger.info('InViewportImageObserver.disconnect()');
     this.lastImageLoadTimestamp = 0;
     this.imageLoadTimes.clear();
     this.intersectionObserver.disconnect();

src/inViewportMutationObserver.ts

@@ -1,3 +1,5 @@
+import {Logger} from './util/logger';
+
 export type InViewportMutationObserverCallback = (mutation: TimestampedMutationRecord) => void;
 export type TimestampedMutationRecord = MutationRecord & {timestamp: number};
 
@@ -39,15 +41,23 @@ export class InViewportMutationObserver {
   }
 
   public observe(target: HTMLElement) {
+    Logger.info('InViewportMutationObserver.observe()', '::', 'target =', target);
     this.mutationObserver.observe(target, this.mutationObserverConfig);
   }
 
   public disconnect() {
+    Logger.info('InViewportMutationObserver.disconnect()');
     this.mutationObserver.disconnect();
     this.intersectionObserver.disconnect();
   }
 
   private mutationObserverCallback: MutationCallback = (mutations) => {
+    Logger.debug(
+      'InViewportMutationObserver.mutationObserverCallback()',
+      '::',
+      'mutations =',
+      mutations
+    );
     mutations.forEach((mutation: TimestampedMutationRecord) => {
       mutation.timestamp = performance.now();
 
@@ -77,10 +87,16 @@ export class InViewportMutationObserver {
   };
 
   private intersectionObserverCallback: IntersectionObserverCallback = (entries) => {
+    Logger.debug(
+      'InViewportMutationObserver.intersectionObserverCallback()',
+      '::',
+      'entries =',
+      entries
+    );
     entries.forEach((entry) => {
-      // console.log(entry);
       if (entry.isIntersecting && this.mutations.has(entry.target)) {
         const mutation = this.mutations.get(entry.target);
+        Logger.info('InViewportMutationObserver.callback()', '::', 'mutation =', mutation);
         this.callback(mutation);
       }
       this.mutations.delete(entry.target);

src/index.ts

@@ -1,4 +1,6 @@
-import {getNetworkIdleObservable} from './networkIdleObservable.js';
+import {getNetworkIdleObservable} from './networkIdleObservable';
+import {TtvcOptions, setConfig} from './util/constants';
+import {Logger} from './util/logger';
 import {
   getVisuallyCompleteCalculator,
   MetricSubscriber,
@@ -7,9 +9,15 @@ import {
 
 let calculator: VisuallyCompleteCalculator;
 
-// Start monitoring initial pageload
-// TODO: Should we ask library consumers to manually initialize?
-export const init = () => {
+/**
+ *  Start ttvc and begin monitoring network activity and visual changes.
+ */
+export const init = (options?: TtvcOptions) => {
+  // apply options
+  setConfig(options);
+
+  Logger.info('init()');
+
   calculator = getVisuallyCompleteCalculator();
   void calculator.start();
   window.addEventListener('locationchange', () => void calculator.start(performance.now()));

src/networkIdleObservable.ts

@@ -1,3 +1,5 @@
+import {Logger} from './util/logger';
+
 export type Message = 'IDLE' | 'BUSY';
 type Subscriber = (message: Message) => void;
 type ResourceLoadingElement = HTMLScriptElement | HTMLLinkElement | HTMLImageElement;
@@ -13,6 +15,7 @@ class AjaxIdleObservable {
   private subscribers = new Set<Subscriber>();
 
   private next = (message: Message) => {
+    Logger.debug('AjaxIdleObservable.next()', message);
     this.subscribers.forEach((subscriber) => subscriber(message));
   };
 
@@ -30,6 +33,14 @@ class AjaxIdleObservable {
       this.next('IDLE');
     }
     this.pendingRequests = Math.max(this.pendingRequests - 1, 0);
+    if (this.pendingRequests < 10) {
+      Logger.debug(
+        'AjaxIdleObservable.decrement()',
+        '::',
+        'pendingRequests =',
+        this.pendingRequests
+      );
+    }
   };
 
   subscribe = (subscriber: Subscriber) => {
@@ -93,6 +104,7 @@ class ResourceLoadingIdleObservable {
   }
 
   private next = (message: Message) => {
+    Logger.debug('ResourceLoadingIdleObservable.next()', message);
     this.subscribers.forEach((subscriber) => subscriber(message));
   };
 
@@ -113,6 +125,14 @@ class ResourceLoadingIdleObservable {
     if (this.pendingResources.size === 0) {
       this.next('IDLE');
     }
+    if (this.pendingResources.size < 10) {
+      Logger.debug(
+        'ResourceLoadingIdleObservable.remove()',
+        '::',
+        'pendingResources =',
+        this.pendingResources
+      );
+    }
   };
 
   subscribe = (subscriber: Subscriber) => {
@@ -164,6 +184,7 @@ export class NetworkIdleObservable {
   };
 
   private next = (message: Message) => {
+    Logger.debug('NetworkIdleObservable.next()', message);
     this.subscribers.forEach((subscriber) => subscriber(message));
   };
 

src/requestAllIdleCallback.ts

@@ -1,10 +1,11 @@
-import {MINIMUM_IDLE_MS} from './constants';
+import {CONFIG} from './util/constants';
 import {Message, getNetworkIdleObservable} from './networkIdleObservable';
-import {requestIdleCallback} from './utils';
+import {requestIdleCallback} from './util';
+import {Logger} from './util/logger';
 
 /**
  * Request a callback when the CPU and network have both been simultaneously
- * idle for MINIMUM_IDLE_MS.
+ * idle for IDLE_TIMEOUT.
  *
  * NOTE: will only trigger once
  */
@@ -16,7 +17,6 @@ export function requestAllIdleCallback(callback: () => void) {
   let timeout: number | null = null;
 
   const handleNetworkChange = (message: Message) => {
-    // console.log('NETWORK', message);
     networkIdle = message === 'IDLE';
 
     if (networkIdle) {
@@ -28,16 +28,18 @@ export function requestAllIdleCallback(callback: () => void) {
   };
 
   const handleCpuIdle = () => {
+    Logger.debug('requestAllIdleCallback.handleCpuIdle()');
     if (networkIdle && !timeout) {
       handleAllIdle();
     }
   };
 
   const handleAllIdle = () => {
     timeout = window.setTimeout(() => {
+      Logger.info('requestAllIdleCallback: ALL IDLE');
       callback();
       unsubscribe();
-    }, MINIMUM_IDLE_MS);
+    }, CONFIG.IDLE_TIMEOUT);
   };
 
   const unsubscribe = networkIdleObservable.subscribe(handleNetworkChange);

src/util/constants.ts

@@ -0,0 +1,17 @@
+export type TtvcOptions = {
+  debug?: boolean;
+  idleTimeout?: number;
+};
+
+/** ttvc configuration values set during initialization */
+export const CONFIG = {
+  /** Decide whether to log debug messages. */
+  DEBUG: false,
+  /** A duration in ms to wait before declaring the page idle. */
+  IDLE_TIMEOUT: 200,
+};
+
+export const setConfig = (options?: TtvcOptions) => {
+  if (options?.debug) CONFIG.DEBUG = options.debug;
+  if (options?.idleTimeout) CONFIG.IDLE_TIMEOUT = options.idleTimeout;
+};

src/util/logger.ts

@@ -0,0 +1,22 @@
+import {CONFIG} from './constants';
+
+export class Logger {
+  private static format(...messages: unknown[]) {
+    return ['[ttvc]', ...messages, '::', performance.now()];
+  }
+  /** Log a debug message to the console */
+  static debug(...messages: unknown[]) {
+    if (!CONFIG.DEBUG) return;
+    console.debug(...this.format(...messages));
+  }
+  /** Log a message to the console */
+  static info(...messages: unknown[]) {
+    if (!CONFIG.DEBUG) return;
+    console.info(...this.format(...messages));
+  }
+  /** Log a warning message to the console */
+  static warn(...messages: unknown[]) {
+    if (!CONFIG.DEBUG) return;
+    console.warn(...this.format(...messages));
+  }
+}

src/visuallyCompleteCalculator.ts

@@ -1,21 +1,26 @@
 import {InViewportMutationObserver} from './inViewportMutationObserver';
-import {waitForPageLoad} from './utils';
+import {waitForPageLoad} from './util';
 import {requestAllIdleCallback} from './requestAllIdleCallback';
 import {InViewportImageObserver} from './inViewportImageObserver';
+import {Logger} from './util/logger';
 
 export type MetricSubscriber = (measurement: number) => void;
 
 /**
  * TODO: Document
  */
 class VisuallyCompleteCalculator {
+  public debug = false;
+  public idleTimeout = 200;
+
   private inViewportMutationObserver: InViewportMutationObserver;
   private inViewportImageObserver: InViewportImageObserver;
 
   // measurement state
   private lastMutationTimestamp = 0;
   private lastImageLoadTimestamp = 0;
   private subscribers = new Set<MetricSubscriber>();
+  private navigationCount = 0;
 
   /**
    * Determine whether the calculator should run in the current environment
@@ -47,6 +52,9 @@ class VisuallyCompleteCalculator {
 
   /** begin measuring a new navigation */
   async start(startTime = 0) {
+    const navigationIndex = (this.navigationCount += 1);
+    Logger.info('VisuallyCompleteCalculator.start()');
+
     // setup
     let shouldCancel = false;
     const cancel = () => (shouldCancel = true);
@@ -76,16 +84,28 @@ class VisuallyCompleteCalculator {
     }
 
     // cleanup
-    this.inViewportImageObserver.disconnect();
-    this.inViewportMutationObserver.disconnect();
     window.removeEventListener('pagehide', cancel);
     window.removeEventListener('visibilitychange', cancel);
     window.removeEventListener('locationchange', cancel);
     window.removeEventListener('click', cancel);
     window.removeEventListener('keydown', cancel);
+    // only disconnect observers if this is the most recent navigation
+    if (navigationIndex === this.navigationCount) {
+      this.inViewportImageObserver.disconnect();
+      this.inViewportMutationObserver.disconnect();
+    }
   }
 
   private next(measurement: number) {
+    Logger.debug(
+      'VisuallyCompleteCalculator.next()',
+      '::',
+      'lastImageLoadTimestamp =',
+      this.lastImageLoadTimestamp,
+      'lastMutationTimestamp =',
+      this.lastMutationTimestamp
+    );
+    Logger.info('TTVC:', measurement);
     this.subscribers.forEach((subscriber) => subscriber(measurement));
   }
 

test/server/public/analytics.js

@@ -8,8 +8,7 @@ window.fetch = (...args) => {
   return oldFetch(...args).finally(TTVC.decrementAjaxCount);
 };
 
-TTVC.init();
-console.log('init');
+TTVC.init({debug: true});
 
 TTVC.getTTVC((ms) => {
   console.log('TTVC:', ms);

test/unit/requestAllIdleCallback.jest.ts

@@ -1,6 +1,6 @@
 import {decrementAjaxCount, incrementAjaxCount} from '../../src';
-import {MINIMUM_IDLE_MS} from '../../src/constants';
 import {requestAllIdleCallback} from '../../src/requestAllIdleCallback';
+import {CONFIG} from '../../src/util/constants';
 import {FUDGE} from '../util/constants';
 
 const wait = async (ms: number) => new Promise((resolve) => window.setTimeout(resolve, ms));
@@ -13,29 +13,29 @@ describe('requestAllIdleCallback', () => {
     requestAllIdleCallback(callback);
   });
 
-  it('waits MINIMUM_IDLE_MS before resolving', async () => {
-    await wait(MINIMUM_IDLE_MS);
+  it('waits IDLE_TIMEOUT before resolving', async () => {
+    await wait(CONFIG.IDLE_TIMEOUT);
     expect(callback).not.toHaveBeenCalled();
     await wait(FUDGE);
     expect(callback).toHaveBeenCalled();
   });
 
   it('respects pending ajax requests', async () => {
     incrementAjaxCount();
-    await wait(MINIMUM_IDLE_MS + FUDGE);
+    await wait(CONFIG.IDLE_TIMEOUT + FUDGE);
     expect(callback).not.toHaveBeenCalled();
 
     decrementAjaxCount();
-    await wait(MINIMUM_IDLE_MS + FUDGE);
+    await wait(CONFIG.IDLE_TIMEOUT + FUDGE);
     expect(callback).toHaveBeenCalled();
   });
 
-  it('does not trigger callback during idle periods less than MINIMUM_IDLE_MS', async () => {
+  it('does not trigger callback during idle periods less than IDLE_TIMEOUT', async () => {
     incrementAjaxCount();
     decrementAjaxCount();
-    await wait(MINIMUM_IDLE_MS / 2);
+    await wait(CONFIG.IDLE_TIMEOUT / 2);
     incrementAjaxCount();
-    await wait(MINIMUM_IDLE_MS + FUDGE);
+    await wait(CONFIG.IDLE_TIMEOUT + FUDGE);
     expect(callback).not.toHaveBeenCalled();
   });
 });