perf: add trace for UI startup (#26636) [cherry-pick] (#26925)

This is a cherry-pick of #26332 and #26636 for v12.2.0, with the TransactionController update removed from #26332. Follow these steps to manually test: * Create a personal Sentry account (if you don't have one already) and create a `metamask` project * Set the DSN of this project as `SENTRY_DSN_DEV` in your `.metamaskrc` file * Create a new dev build * Install the build and go through onboarding, ensuring that you opt-in to metrics * Make a few page navigations You should see the UI traces in the Sentry performance dashboard on your personal account. This was cherry-picked to get the benefits described in #26636 (#26332 was partially included only out of necessity). The original description of #26636 is below: ## **Description** Record a `UI Startup` Sentry trace to monitor startup times of the UI pages. In addition: - Support use of `trace` utility function in non-asynchronous contexts. - Remove `getMetaMetricsEnabled` check as this is already done in the custom transport before submission. - Generate default ID if omitted when starting and ending traces. [![Open in GitHub Codespaces](https://github.com/codespaces/badge.svg)](https://codespaces.new/MetaMask/metamask-extension/pull/26636?quickstart=1) ## **Related issues** Fixes: #25724 ## **Manual testing steps** ## **Screenshots/Recordings** ### **Before** ### **After** <img width="966" alt="Sentry" src="https://github.com/user-attachments/assets/355e835c-24c0-42e6-ab06-4b549c2c7973"> <img width="705" alt="Console" src="https://github.com/user-attachments/assets/211c5445-ee05-4e5f-8de5-e60e8e3133d3"> ## **Pre-merge author checklist** - [x] I've followed [MetaMask Contributor Docs](https://github.com/MetaMask/contributor-docs) and [MetaMask Extension Coding Standards](https://github.com/MetaMask/metamask-extension/blob/develop/.github/guidelines/CODING_GUIDELINES.md). - [x] I've completed the PR template to the best of my ability - [x] I’ve included tests if applicable - [x] I’ve documented my code using [JSDoc](https://jsdoc.app/) format if applicable - [x] I’ve applied the right labels on the PR (see [labeling guidelines](https://github.com/MetaMask/metamask-extension/blob/develop/.github/guidelines/LABELING_GUIDELINES.md)). Not required for external contributors. ## **Pre-merge reviewer checklist** - [ ] I've manually tested the PR (e.g. pull and build branch, run the app, test code being changed). - [ ] I confirm that this PR addresses all acceptance criteria described in the ticket it closes and includes the necessary testing evidence such as recordings and or screenshots. --------- Co-authored-by: Matthew Walsh <[email protected]>
MetaMask · Sep 6, 2024 · 7cc4af7 · 7cc4af7
1 parent a60dbcb
commit 7cc4af7
Show file tree

Hide file tree

Showing 7 changed files with 460 additions and 121 deletions.
diff --git a/app/scripts/lib/setupSentry.js b/app/scripts/lib/setupSentry.js
@@ -82,7 +82,7 @@ function getClientOptions() {
     // we can safely turn them off by setting the `sendClientReports` option to
     // `false`.
     sendClientReports: false,
-    tracesSampleRate: 0.01,
+    tracesSampleRate: METAMASK_DEBUG ? 1.0 : 0.01,
     transport: makeTransport,
   };
 }

diff --git a/app/scripts/metamask-controller.js b/app/scripts/metamask-controller.js
@@ -213,6 +213,7 @@ import {
   TOKEN_TRANSFER_LOG_TOPIC_HASH,
   TRANSFER_SINFLE_LOG_TOPIC_HASH,
 } from '../../shared/lib/transactions-controller-utils';
+import { endTrace } from '../../shared/lib/trace';
 import { BalancesController as MultichainBalancesController } from './lib/accounts/BalancesController';
 import {
   ///: BEGIN:ONLY_INCLUDE_IF(build-mmi)
@@ -3769,6 +3770,9 @@ export default class MetamaskController extends EventEmitter {
           ...request,
           ethQuery: new EthQuery(this.provider),
         }),
+
+      // Trace
+      endTrace,
     };
   }
 

diff --git a/app/scripts/ui.js b/app/scripts/ui.js
@@ -24,6 +24,7 @@ import { isManifestV3 } from '../../shared/modules/mv3.utils';
 import { checkForLastErrorAndLog } from '../../shared/modules/browser-runtime.utils';
 import { SUPPORT_LINK } from '../../shared/lib/ui-utils';
 import { getErrorHtml } from '../../shared/lib/error-utils';
+import { endTrace, trace, TraceName } from '../../shared/lib/trace';
 import ExtensionPlatform from './platforms/extension';
 import { setupMultiplex } from './lib/stream-utils';
 import { getEnvironmentType, getPlatform } from './lib/util';
@@ -43,6 +44,24 @@ let extensionPort;
 start().catch(log.error);
 
 async function start() {
+  const startTime = performance.now();
+
+  const traceContext = trace({
+    name: TraceName.UIStartup,
+    startTime: performance.timeOrigin,
+  });
+
+  trace({
+    name: TraceName.LoadScripts,
+    startTime: performance.timeOrigin,
+    parentContext: traceContext,
+  });
+
+  endTrace({
+    name: 'Load Scripts',
+    timestamp: performance.timeOrigin + startTime,
+  });
+
   // create platform global
   global.platform = new ExtensionPlatform();
 
@@ -74,6 +93,7 @@ async function start() {
           // in later version we might try to improve it by reviving same streams.
           updateUiStreams();
         } else {
+          endTrace({ name: TraceName.BackgroundConnect });
           initializeUiWithTab(activeTab);
         }
         await loadPhishingWarningPage();
@@ -189,18 +209,30 @@ async function start() {
 
     extensionPort.onMessage.addListener(messageListener);
     extensionPort.onDisconnect.addListener(resetExtensionStreamAndListeners);
+
+    trace({
+      name: TraceName.BackgroundConnect,
+      parentContext: traceContext,
+    });
   } else {
     const messageListener = async (message) => {
       if (message?.data?.method === 'startUISync') {
+        endTrace({ name: TraceName.BackgroundConnect });
         initializeUiWithTab(activeTab);
         extensionPort.onMessage.removeListener(messageListener);
       }
     };
+
     extensionPort.onMessage.addListener(messageListener);
+
+    trace({
+      name: TraceName.BackgroundConnect,
+      parentContext: traceContext,
+    });
   }
 
   function initializeUiWithTab(tab) {
-    initializeUi(tab, connectionStream, (err, store) => {
+    initializeUi(tab, connectionStream, traceContext, (err, store) => {
       if (err) {
         // if there's an error, store will be = metamaskState
         displayCriticalError('troubleStarting', err, store);
@@ -276,7 +308,7 @@ async function queryCurrentActiveTab(windowType) {
   return { id, title, origin, protocol, url };
 }
 
-function initializeUi(activeTab, connectionStream, cb) {
+function initializeUi(activeTab, connectionStream, traceContext, cb) {
   connectToAccountManager(connectionStream, (err, backgroundConnection) => {
     if (err) {
       cb(err, null);
@@ -288,6 +320,7 @@ function initializeUi(activeTab, connectionStream, cb) {
         activeTab,
         container,
         backgroundConnection,
+        traceContext,
       },
       cb,
     );

diff --git a/shared/lib/trace.test.ts b/shared/lib/trace.test.ts
@@ -1,12 +1,19 @@
-import { Span, startSpan, withIsolationScope } from '@sentry/browser';
-import { trace } from './trace';
+import {
+  Span,
+  startSpan,
+  startSpanManual,
+  withIsolationScope,
+} from '@sentry/browser';
+import { endTrace, trace, TraceName } from './trace';
 
 jest.mock('@sentry/browser', () => ({
   withIsolationScope: jest.fn(),
   startSpan: jest.fn(),
+  startSpanManual: jest.fn(),
 }));
 
-const NAME_MOCK = 'testTransaction';
+const NAME_MOCK = TraceName.Transaction;
+const ID_MOCK = 'testId';
 const PARENT_CONTEXT_MOCK = {} as Span;
 
 const TAGS_MOCK = {
@@ -21,14 +28,9 @@ const DATA_MOCK = {
   data3: 123,
 };
 
-function mockGetMetaMetricsEnabled(enabled: boolean) {
-  global.sentry = {
-    getMetaMetricsEnabled: () => Promise.resolve(enabled),
-  };
-}
-
 describe('Trace', () => {
   const startSpanMock = jest.mocked(startSpan);
+  const startSpanManualMock = jest.mocked(startSpanManual);
   const withIsolationScopeMock = jest.mocked(withIsolationScope);
   const setTagsMock = jest.fn();
 
@@ -44,53 +46,30 @@ describe('Trace', () => {
   });
 
   describe('trace', () => {
-    // @ts-expect-error This function is missing from the Mocha type definitions
-    it.each([
-      ['enabled', true],
-      ['disabled', false],
-    ])(
-      'executes callback if Sentry is %s',
-      async (_: string, sentryEnabled: boolean) => {
-        let callbackExecuted = false;
-
-        mockGetMetaMetricsEnabled(sentryEnabled);
-
-        await trace({ name: NAME_MOCK }, async () => {
-          callbackExecuted = true;
-        });
-
-        expect(callbackExecuted).toBe(true);
-      },
-    );
+    it('executes callback', () => {
+      let callbackExecuted = false;
 
-    // @ts-expect-error This function is missing from the Mocha type definitions
-    it.each([
-      ['enabled', true],
-      ['disabled', false],
-    ])(
-      'returns value from callback if Sentry is %s',
-      async (_: string, sentryEnabled: boolean) => {
-        mockGetMetaMetricsEnabled(sentryEnabled);
-
-        const result = await trace({ name: NAME_MOCK }, async () => {
-          return true;
-        });
-
-        expect(result).toBe(true);
-      },
-    );
+      trace({ name: NAME_MOCK }, () => {
+        callbackExecuted = true;
+      });
 
-    it('invokes Sentry if enabled', async () => {
-      mockGetMetaMetricsEnabled(true);
+      expect(callbackExecuted).toBe(true);
+    });
 
-      await trace(
+    it('returns value from callback', () => {
+      const result = trace({ name: NAME_MOCK }, () => true);
+      expect(result).toBe(true);
+    });
+
+    it('invokes Sentry if callback provided', () => {
+      trace(
         {
           name: NAME_MOCK,
           tags: TAGS_MOCK,
           data: DATA_MOCK,
           parentContext: PARENT_CONTEXT_MOCK,
         },
-        async () => Promise.resolve(),
+        () => true,
       );
 
       expect(withIsolationScopeMock).toHaveBeenCalledTimes(1);
@@ -101,12 +80,161 @@ describe('Trace', () => {
           name: NAME_MOCK,
           parentSpan: PARENT_CONTEXT_MOCK,
           attributes: DATA_MOCK,
+          op: 'custom',
         },
         expect.any(Function),
       );
 
       expect(setTagsMock).toHaveBeenCalledTimes(1);
       expect(setTagsMock).toHaveBeenCalledWith(TAGS_MOCK);
     });
+
+    it('invokes Sentry if no callback provided', () => {
+      trace({
+        id: ID_MOCK,
+        name: NAME_MOCK,
+        tags: TAGS_MOCK,
+        data: DATA_MOCK,
+        parentContext: PARENT_CONTEXT_MOCK,
+      });
+
+      expect(withIsolationScopeMock).toHaveBeenCalledTimes(1);
+
+      expect(startSpanManualMock).toHaveBeenCalledTimes(1);
+      expect(startSpanManualMock).toHaveBeenCalledWith(
+        {
+          name: NAME_MOCK,
+          parentSpan: PARENT_CONTEXT_MOCK,
+          attributes: DATA_MOCK,
+          op: 'custom',
+        },
+        expect.any(Function),
+      );
+
+      expect(setTagsMock).toHaveBeenCalledTimes(1);
+      expect(setTagsMock).toHaveBeenCalledWith(TAGS_MOCK);
+    });
+
+    it('invokes Sentry if no callback provided with custom start time', () => {
+      trace({
+        id: ID_MOCK,
+        name: NAME_MOCK,
+        tags: TAGS_MOCK,
+        data: DATA_MOCK,
+        parentContext: PARENT_CONTEXT_MOCK,
+        startTime: 123,
+      });
+
+      expect(withIsolationScopeMock).toHaveBeenCalledTimes(1);
+
+      expect(startSpanManualMock).toHaveBeenCalledTimes(1);
+      expect(startSpanManualMock).toHaveBeenCalledWith(
+        {
+          name: NAME_MOCK,
+          parentSpan: PARENT_CONTEXT_MOCK,
+          attributes: DATA_MOCK,
+          op: 'custom',
+          startTime: 123,
+        },
+        expect.any(Function),
+      );
+
+      expect(setTagsMock).toHaveBeenCalledTimes(1);
+      expect(setTagsMock).toHaveBeenCalledWith(TAGS_MOCK);
+    });
+  });
+
+  describe('endTrace', () => {
+    it('ends Sentry span matching name and specified ID', () => {
+      const spanEndMock = jest.fn();
+      const spanMock = { end: spanEndMock } as unknown as Span;
+
+      startSpanManualMock.mockImplementationOnce((_, fn) =>
+        fn(spanMock, () => {
+          // Intentionally empty
+        }),
+      );
+
+      trace({
+        name: NAME_MOCK,
+        id: ID_MOCK,
+        tags: TAGS_MOCK,
+        data: DATA_MOCK,
+        parentContext: PARENT_CONTEXT_MOCK,
+      });
+
+      endTrace({ name: NAME_MOCK, id: ID_MOCK });
+
+      expect(spanEndMock).toHaveBeenCalledTimes(1);
+    });
+
+    it('ends Sentry span matching name and default ID', () => {
+      const spanEndMock = jest.fn();
+      const spanMock = { end: spanEndMock } as unknown as Span;
+
+      startSpanManualMock.mockImplementationOnce((_, fn) =>
+        fn(spanMock, () => {
+          // Intentionally empty
+        }),
+      );
+
+      trace({
+        name: NAME_MOCK,
+        tags: TAGS_MOCK,
+        data: DATA_MOCK,
+        parentContext: PARENT_CONTEXT_MOCK,
+      });
+
+      endTrace({ name: NAME_MOCK });
+
+      expect(spanEndMock).toHaveBeenCalledTimes(1);
+    });
+
+    it('ends Sentry span with custom timestamp', () => {
+      const spanEndMock = jest.fn();
+      const spanMock = { end: spanEndMock } as unknown as Span;
+
+      startSpanManualMock.mockImplementationOnce((_, fn) =>
+        fn(spanMock, () => {
+          // Intentionally empty
+        }),
+      );
+
+      trace({
+        name: NAME_MOCK,
+        id: ID_MOCK,
+        tags: TAGS_MOCK,
+        data: DATA_MOCK,
+        parentContext: PARENT_CONTEXT_MOCK,
+      });
+
+      endTrace({ name: NAME_MOCK, id: ID_MOCK, timestamp: 123 });
+
+      expect(spanEndMock).toHaveBeenCalledTimes(1);
+      expect(spanEndMock).toHaveBeenCalledWith(123);
+    });
+
+    it('does not end Sentry span if name and ID does not match', () => {
+      const spanEndMock = jest.fn();
+      const spanMock = { end: spanEndMock } as unknown as Span;
+
+      startSpanManualMock.mockImplementationOnce((_, fn) =>
+        fn(spanMock, () => {
+          // Intentionally empty
+        }),
+      );
+
+      trace({
+        name: NAME_MOCK,
+        id: ID_MOCK,
+        tags: TAGS_MOCK,
+        data: DATA_MOCK,
+        parentContext: PARENT_CONTEXT_MOCK,
+      });
+
+      endTrace({ name: NAME_MOCK, id: 'invalidId' });
+
+      expect(spanEndMock).toHaveBeenCalledTimes(0);
+    });
   });
 });