report first steady ping after initial resources loaded

Author: vzaidman

front_end/core/host/RNPerfMetrics.ts

@@ -29,6 +29,7 @@ class RNPerfMetrics {
   #telemetryInfo: Object = {};
   // map of panel location to panel name
   #currentPanels = new Map<PanelLocation, string>();
+  #initialResourcesLoadedInfo: null|{count: number, time: number} = null;
 
   isEnabled(): boolean {
     return globalThis.enableReactNativePerfMetrics === true;
@@ -186,13 +187,10 @@ class RNPerfMetrics {
     });
   }
 
-  allInitialDeveloperResourcesLoadingFinished(count: number): void {
-    this.sendEvent({
-      eventName: 'DeveloperResource.AllInitialLoadingFinished',
-      params: {
-        count,
-      },
-    });
+  initialResourcesLoaded(info: {count: number, time: number}): void {
+    // eslint-disable-next-line no-console
+    console.info('Initial %d resources are loaded at %sms since launch', info.count, info.time);
+    this.#initialResourcesLoadedInfo = info;
   }
 
   fuseboxSetClientMetadataStarted(): void {
@@ -215,10 +213,30 @@ class RNPerfMetrics {
     }
   }
 
-  firstSteadyPing(): void {
+  tryReportingCdpLowRoundtrip(cdpLowRoundtripStartTime: number): boolean {
+    if (this.#initialResourcesLoadedInfo === null) {
+      return false;
+    }
+
+    // if the roundtrip is fine for a long time, just take the initial resources loading time
+    // if it got better only after the initial resources were loaded, take the cdp low roundtrip time instead
+    const startupTime = Math.max(cdpLowRoundtripStartTime, this.#initialResourcesLoadedInfo.time);
+
+    // eslint-disable-next-line no-console
+    console.info('The app had a low CDP roundtrip at %sms since launch', cdpLowRoundtripStartTime);
+    // eslint-disable-next-line no-console
+    console.info('Startup time is %sms', startupTime);
+
     this.sendEvent({
-      eventName: 'FirstSteadyPing',
+      eventName: 'StartUpFinished',
+      params: {
+        bundleCount: this.#initialResourcesLoadedInfo.count,
+        duration: startupTime,
+        initialResourcesLoadedTime: this.#initialResourcesLoadedInfo.time,
+        cdpLowRoundtripStartTime,
+      }
     });
+    return true;
   }
 
   heapSnapshotStarted(): void {
@@ -432,13 +450,6 @@ export type DeveloperResourceLoadingFinishedEvent = Readonly<{
   }>,
 }>;
 
-export type AllInitialDeveloperResourcesLoadingFinished = Readonly<{
-  eventName: 'DeveloperResource.AllInitialLoadingFinished',
-  params: Readonly<{
-    count: number,
-  }>,
-}>;
-
 export type FuseboxSetClientMetadataStartedEvent = Readonly<{
   eventName: 'FuseboxSetClientMetadataStarted',
 }>;
@@ -511,16 +522,22 @@ export type StackTraceFrameUrlResolutionFailed = Readonly<{
   }>,
 }>;
 
-export type FirstSteadyPing = Readonly<{
-  eventName: 'FirstSteadyPing',
+export type StartUpFinished = Readonly<{
+  eventName: 'StartUpFinished',
+  params: Readonly<{
+    bundleCount: number,
+    duration: number,
+    initialResourcesLoadedTime: number,
+    cdpLowRoundtripStartTime: number,
+  }>,
 }>;
 
 export type ReactNativeChromeDevToolsEvent =
     EntrypointLoadingStartedEvent|EntrypointLoadingFinishedEvent|DebuggerReadyEvent|BrowserVisibilityChangeEvent|
     BrowserErrorEvent|RemoteDebuggingTerminatedEvent|DeveloperResourceLoadingStartedEvent|
-    DeveloperResourceLoadingFinishedEvent|AllInitialDeveloperResourcesLoadingFinished|FuseboxSetClientMetadataStartedEvent|
+    DeveloperResourceLoadingFinishedEvent|FuseboxSetClientMetadataStartedEvent|
     FuseboxSetClientMetadataFinishedEvent|MemoryPanelActionStartedEvent|MemoryPanelActionFinishedEvent|
     PanelShownEvent|PanelClosedEvent|StackTraceSymbolicationSucceeded|StackTraceSymbolicationFailed|
-    StackTraceFrameUrlResolutionSucceeded|StackTraceFrameUrlResolutionFailed|FirstSteadyPing;
+    StackTraceFrameUrlResolutionSucceeded|StackTraceFrameUrlResolutionFailed|StartUpFinished;
 
 export type DecoratedReactNativeChromeDevToolsEvent = CommonEventFields&ReactNativeChromeDevToolsEvent;

front_end/core/sdk/PageResourceLoader.ts

@@ -29,6 +29,8 @@ const UIStrings = {
 const str_ = i18n.i18n.registerUIStrings('core/sdk/PageResourceLoader.ts', UIStrings);
 const i18nString = i18n.i18n.getLocalizedString.bind(undefined, str_);
 
+const MS_WAIT_ENSURING_ALL_RESOUCES_ARE_LOADED = 3000;
+
 export interface ExtensionInitiator {
   target: null;
   frameId: null;
@@ -82,7 +84,8 @@ interface LoadQueueEntry {
  */
 export class PageResourceLoader extends Common.ObjectWrapper.ObjectWrapper<EventTypes> {
   #currentlyLoading = 0;
-  #reportedAllInitialResourcesLoaded = false;
+  #initialResourcesLoadedTimeout: number|null = null;
+  #reportedInitialResourcesLoaded = false;
   #currentlyLoadingPerTarget = new Map<Protocol.Target.TargetID|'main', number>();
   readonly #maxConcurrentLoads: number;
   #pageResources = new Map<string, PageResource>();
@@ -356,13 +359,22 @@ export class PageResourceLoader extends Common.ObjectWrapper.ObjectWrapper<Event
     Host.rnPerfMetrics.developerResourceLoadingFinished(
         parsedURL, Host.UserMetrics.DeveloperResourceLoaded.FALLBACK_AFTER_FAILURE, result);
 
-    // Will be decreased to 0 right after this function in "releaseLoadSlot".
-    // Tracking it here so it is next to the rest of "rnPerfMetrics" in this file.
-    const allResourcesLoaded = this.#currentlyLoading === 1;
-    if (allResourcesLoaded && !this.#reportedAllInitialResourcesLoaded) {
-      Host.rnPerfMetrics.allInitialDeveloperResourcesLoadingFinished(this.getNumberOfResources().resources);
-      this.#reportedAllInitialResourcesLoaded = true;
+    // Wait for several seconds to ensure no new resources were loaded,
+    // possibly by the resources that just finished loading
+    const resourceLoadingTime = performance.now();
+    if (this.#initialResourcesLoadedTimeout) {
+      window.clearTimeout(this.#initialResourcesLoadedTimeout);
     }
+    this.#initialResourcesLoadedTimeout = window.setTimeout(() => {
+      const allResourcesLoaded = this.#currentlyLoading === 0;
+      if (allResourcesLoaded && !this.#reportedInitialResourcesLoaded) {
+        Host.rnPerfMetrics.initialResourcesLoaded({
+          count: this.getNumberOfResources().resources,
+          time: Math.round(resourceLoadingTime)
+        });
+        this.#reportedInitialResourcesLoaded = true;
+      }
+    }, MS_WAIT_ENSURING_ALL_RESOUCES_ARE_LOADED);
 
     return result;
   }

front_end/entrypoints/inspector_main/InspectorMain.ts

@@ -15,8 +15,8 @@ import * as UI from '../../ui/legacy/legacy.js';
 
 import nodeIconStyles from './nodeIcon.css.js';
 
-const COOLDOWN_BETWEEN_PINGS = 3000;
-const LOW_PING_THRESHOLD = 200;
+const MS_BETWEEN_ROUNDTRIP_MEASUREMENTS = 3000;
+const MS_MAX_LOW_ROUNDTRIP = 200;
 
 const UIStrings = {
   /**
@@ -49,7 +49,7 @@ const i18nString = i18n.i18n.getLocalizedString.bind(undefined, str_);
 let inspectorMainImplInstance: InspectorMainImpl;
 
 export class InspectorMainImpl implements Common.Runnable.Runnable {
-  #consecutiveLowPing = 0;
+  #consecutiveLowRoundtrips = 0;
 
   static instance(opts: {
     forceNew: boolean|null,
@@ -62,25 +62,37 @@ export class InspectorMainImpl implements Common.Runnable.Runnable {
     return inspectorMainImplInstance;
   }
 
-  async #measureMainConnectionPing(debuggerModel: SDK.DebuggerModel.DebuggerModel): Promise<void> {
+  async #measureMainConnectionRoundtrip(debuggerModel: SDK.DebuggerModel.DebuggerModel): Promise<void> {
     if (!debuggerModel.debuggerEnabled()) {
       return;
     }
 
     const startMs = Date.now();
+    // Issues and waits for a response from a simple "Debugger.enable" when the debugger is enabled
+    // which noops and retuns a truthy response:
+    // https://github.com/facebook/hermes/blob/ae235193b9329867afaa2838183cbffa34aca098/API/hermes/cdp/DebuggerDomainAgent.cpp#L224-L228
+    // https://github.com/facebook/hermes/blob/ae235193b9329867afaa2838183cbffa34aca098/API/hermes/cdp/DebuggerDomainAgent.cpp#L183-L185
+    // It measures the round trip time for CDP message after being queued in the CDP queue in each direction.
     await debuggerModel.syncDebuggerId();
-    const ping = Date.now() - startMs;
+    const roundtripTime = Date.now() - startMs;
 
-    if (ping > LOW_PING_THRESHOLD) {
-      this.#consecutiveLowPing = 0;
+    if (roundtripTime > MS_MAX_LOW_ROUNDTRIP) {
+      this.#consecutiveLowRoundtrips = 0;
     } else {
-      this.#consecutiveLowPing++;
+      this.#consecutiveLowRoundtrips++;
     }
 
-    if (this.#consecutiveLowPing > 1) {
-      Host.rnPerfMetrics.firstSteadyPing();
-    } else {
-      setTimeout(() => void this.#measureMainConnectionPing(debuggerModel), COOLDOWN_BETWEEN_PINGS);
+    let reportedLowRoundrip = false;
+    if (this.#consecutiveLowRoundtrips >= 2) {
+      reportedLowRoundrip = Host.rnPerfMetrics.tryReportingCdpLowRoundtrip(
+        Math.round(performance.now() - ((this.#consecutiveLowRoundtrips - 1) * MS_BETWEEN_ROUNDTRIP_MEASUREMENTS))
+      );
+    }
+
+    if (!reportedLowRoundrip) {
+      setTimeout(() => {
+        void this.#measureMainConnectionRoundtrip(debuggerModel);
+      }, MS_BETWEEN_ROUNDTRIP_MEASUREMENTS);
     }
   }
 
@@ -123,7 +135,7 @@ export class InspectorMainImpl implements Common.Runnable.Runnable {
 
       const debuggerModel = target.model(SDK.DebuggerModel.DebuggerModel);
       if (debuggerModel) {
-        void this.#measureMainConnectionPing(debuggerModel);
+        void this.#measureMainConnectionRoundtrip(debuggerModel);
         if (waitForDebuggerInPage) {
             if (!debuggerModel.isReadyToPause()) {
               await debuggerModel.once(SDK.DebuggerModel.Events.DebuggerIsReadyToPause);