feat(multichain-account-service): add local perf tracing (debug) + more traces

packages/multichain-account-service/CHANGELOG.md

@@ -15,6 +15,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
   - This behavior was enabled by default and can now be turned off by the clients.
 - Add new `snapPlatformWatcher.timeoutMs` configuration ([#8196](https://github.com/MetaMask/core/pull/8196))
   - Allows configuring how long to wait for the Snap keyring to appear in `KeyringController` before timing out (Default is 5000 ms).
+- Add more tracing (alignment, create account v1/v2) ([#8244](https://github.com/MetaMask/core/pull/8244))
+- Add local perf tracing ([#8244](https://github.com/MetaMask/core/pull/8244))
+  - Each traces are now automatically wrapped and will log performance timings using the internal logger.
+  - Only enabled if `metamask:multichain-account-service` is part of `DEBUG` (env var) filters.
 
 ### Changed
 

packages/multichain-account-service/package.json

@@ -70,6 +70,7 @@
   "devDependencies": {
     "@metamask/account-api": "^1.0.0",
     "@metamask/auto-changelog": "^3.4.4",
+    "@metamask/controller-utils": "^11.19.0",
     "@metamask/eth-hd-keyring": "^13.0.0",
     "@metamask/providers": "^22.1.0",
     "@ts-bridge/cli": "^0.6.4",

packages/multichain-account-service/src/MultichainAccountService.test.ts

@@ -12,6 +12,8 @@ import {
 import type { KeyringObject } from '@metamask/keyring-controller';
 import type { EthKeyring } from '@metamask/keyring-internal-api';
 
+import { traceFallback } from './analytics';
+import { isPerfEnabled, withLocalPerfTrace } from './analytics/perf';
 import type { MultichainAccountServiceOptions } from './MultichainAccountService';
 import { MultichainAccountService } from './MultichainAccountService';
 import type { Bip44AccountProvider } from './providers';
@@ -48,6 +50,12 @@ import {
 } from './tests';
 import type { MultichainAccountServiceMessenger } from './types';
 
+// Mock perf helpers so tests can control isPerfEnabled() without setting DEBUG env var.
+jest.mock('./analytics/perf', () => ({
+  isPerfEnabled: jest.fn().mockReturnValue(false),
+  withLocalPerfTrace: jest.fn((trace) => trace),
+}));
+
 // Mock providers.
 jest.mock('./providers/EvmAccountProvider', () => {
   return {
@@ -136,11 +144,13 @@ async function setup({
   keyrings = [MOCK_HD_KEYRING_1, MOCK_HD_KEYRING_2],
   accounts,
   providerConfigs,
+  config,
 }: {
   rootMessenger?: RootMessenger;
   keyrings?: KeyringObject[];
   accounts?: KeyringAccount[];
   providerConfigs?: MultichainAccountServiceOptions['providerConfigs'];
+  config?: MultichainAccountServiceOptions['config'];
 } = {}): Promise<{
   service: MultichainAccountService;
   rootMessenger: RootMessenger;
@@ -264,6 +274,7 @@ async function setup({
   const service = new MultichainAccountService({
     messenger,
     providerConfigs,
+    config,
   });
 
   await service.init();
@@ -321,6 +332,90 @@ describe('MultichainAccountService', () => {
       );
     });
 
+    it('passes traceFallback to providers when no config.trace is provided and perf is disabled', async () => {
+      jest.mocked(isPerfEnabled).mockReturnValue(false);
+
+      const { mocks, messenger } = await setup({
+        accounts: [MOCK_HD_ACCOUNT_1, MOCK_SOL_ACCOUNT_1],
+      });
+
+      expect(withLocalPerfTrace).not.toHaveBeenCalled();
+      expect(mocks.EvmAccountProvider.constructor).toHaveBeenCalledWith(
+        messenger,
+        undefined,
+        traceFallback,
+      );
+      expect(mocks.SolAccountProvider.constructor).toHaveBeenCalledWith(
+        messenger,
+        undefined,
+        traceFallback,
+      );
+    });
+
+    it('passes config.trace to providers when provided and perf is disabled', async () => {
+      jest.mocked(isPerfEnabled).mockReturnValue(false);
+      const customTrace = jest.fn();
+
+      const { mocks, messenger } = await setup({
+        accounts: [MOCK_HD_ACCOUNT_1, MOCK_SOL_ACCOUNT_1],
+        config: { trace: customTrace },
+      });
+
+      expect(withLocalPerfTrace).not.toHaveBeenCalled();
+      expect(mocks.EvmAccountProvider.constructor).toHaveBeenCalledWith(
+        messenger,
+        undefined,
+        customTrace,
+      );
+      expect(mocks.SolAccountProvider.constructor).toHaveBeenCalledWith(
+        messenger,
+        undefined,
+        customTrace,
+      );
+    });
+
+    it('wraps trace with local perf trace and passes it to providers when perf is enabled', async () => {
+      jest.mocked(isPerfEnabled).mockReturnValue(true);
+      const wrappedTrace = jest.fn();
+      jest.mocked(withLocalPerfTrace).mockReturnValue(wrappedTrace);
+
+      const { mocks, messenger } = await setup({
+        accounts: [MOCK_HD_ACCOUNT_1, MOCK_SOL_ACCOUNT_1],
+      });
+
+      expect(withLocalPerfTrace).toHaveBeenCalledTimes(1);
+      expect(withLocalPerfTrace).toHaveBeenCalledWith(traceFallback);
+      expect(mocks.EvmAccountProvider.constructor).toHaveBeenCalledWith(
+        messenger,
+        undefined,
+        wrappedTrace,
+      );
+      expect(mocks.SolAccountProvider.constructor).toHaveBeenCalledWith(
+        messenger,
+        undefined,
+        wrappedTrace,
+      );
+    });
+
+    it('wraps config.trace with local perf trace when perf is enabled', async () => {
+      jest.mocked(isPerfEnabled).mockReturnValue(true);
+      const customTrace = jest.fn();
+      const wrappedTrace = jest.fn();
+      jest.mocked(withLocalPerfTrace).mockReturnValue(wrappedTrace);
+
+      const { mocks } = await setup({
+        accounts: [MOCK_HD_ACCOUNT_1, MOCK_SOL_ACCOUNT_1],
+        config: { trace: customTrace },
+      });
+
+      expect(withLocalPerfTrace).toHaveBeenCalledWith(customTrace);
+      expect(mocks.EvmAccountProvider.constructor).toHaveBeenCalledWith(
+        expect.anything(),
+        undefined,
+        wrappedTrace,
+      );
+    });
+
     it('allows optional configs for some providers', async () => {
       const providerConfigs: MultichainAccountServiceOptions['providerConfigs'] =
         {

packages/multichain-account-service/src/MultichainAccountService.ts

@@ -6,13 +6,15 @@ import type {
   MultichainAccountWalletId,
   Bip44Account,
 } from '@metamask/account-api';
+import type { TraceCallback } from '@metamask/controller-utils';
 import type { HdKeyring } from '@metamask/eth-hd-keyring';
 import type { EntropySourceId, KeyringAccount } from '@metamask/keyring-api';
 import { KeyringTypes } from '@metamask/keyring-controller';
 import type { InternalAccount } from '@metamask/keyring-internal-api';
 import { areUint8ArraysEqual, assert } from '@metamask/utils';
 
 import { traceFallback } from './analytics';
+import { isPerfEnabled, withLocalPerfTrace } from './analytics/perf';
 import { reportError } from './errors';
 import { projectLogger as log } from './logger';
 import type { MultichainAccountGroup } from './MultichainAccountGroup';
@@ -121,6 +123,8 @@ export class MultichainAccountService {
 
   readonly #providers: Bip44AccountProvider[];
 
+  readonly #trace: TraceCallback;
+
   readonly #wallets: Map<
     MultichainAccountWalletId,
     MultichainAccountWallet<Bip44Account<KeyringAccount>>
@@ -153,23 +157,31 @@ export class MultichainAccountService {
     this.#messenger = messenger;
     this.#wallets = new Map();
 
-    // Pass trace callback directly to preserve original 'this' context
-    // This avoids binding the callback to the MultichainAccountService instance
-    const traceCallback = config?.trace ?? traceFallback;
+    // Pass trace callback directly to preserve original 'this' context.
+    // This avoids binding the callback to the MultichainAccountService instance.
+    let trace: TraceCallback = config?.trace ?? traceFallback;
+
+    // Wrap the trace callback with local performance tracing if performance logging is enabled.
+    if (isPerfEnabled()) {
+      trace = withLocalPerfTrace(trace);
+    }
+
+    // This trace is passed down to wallets and providers to be used for tracing operations within them.
+    this.#trace = trace;
 
     // TODO: Rely on keyring capabilities once the keyring API is used by all keyrings.
     this.#providers = [
       new EvmAccountProvider(
         this.#messenger,
         providerConfigs?.[EVM_ACCOUNT_PROVIDER_NAME],
-        traceCallback,
+        trace,
       ),
       new AccountProviderWrapper(
         this.#messenger,
         new SolAccountProvider(
           this.#messenger,
           providerConfigs?.[SOL_ACCOUNT_PROVIDER_NAME],
-          traceCallback,
+          trace,
         ),
       ),
       // Custom account providers that can be provided by the MetaMask client.
@@ -264,6 +276,7 @@ export class MultichainAccountService {
         entropySource,
         providers: this.#providers,
         messenger: this.#messenger,
+        trace: this.#trace,
       });
       wallet.init(serviceState[entropySource]);
       this.#wallets.set(wallet.id, wallet);
@@ -410,6 +423,7 @@ export class MultichainAccountService {
       providers: this.#providers,
       entropySource: result.id,
       messenger: this.#messenger,
+      trace: this.#trace,
     });
   }
 
@@ -434,6 +448,7 @@ export class MultichainAccountService {
       providers: this.#providers,
       entropySource: entropySourceId,
       messenger: this.#messenger,
+      trace: this.#trace,
     });
   }
 
@@ -461,6 +476,7 @@ export class MultichainAccountService {
       providers: this.#providers,
       entropySource: entropySourceId,
       messenger: this.#messenger,
+      trace: this.#trace,
     });
   }
 

packages/multichain-account-service/src/MultichainAccountWallet.test.ts

@@ -14,6 +14,7 @@ import {
   AccountCreationType,
 } from '@metamask/keyring-api';
 import type { InternalAccount } from '@metamask/keyring-internal-api';
+import { createDeferredPromise } from '@metamask/utils';
 
 import type { WalletState } from './MultichainAccountWallet';
 import { MultichainAccountWallet } from './MultichainAccountWallet';
@@ -542,19 +543,31 @@ describe('MultichainAccountWallet', () => {
       ];
       evmProvider.createAccounts.mockResolvedValueOnce(evmAccounts);
 
-      jest.spyOn(wallet, 'alignAccounts').mockResolvedValue(undefined);
+      // We use a non-resolving mock for SOL provider because we want to verify
+      // that it's not called during group creation, but rather during the deferred alignment.
+      const {
+        promise: mockSolCreateAccountsPromise,
+        resolve: mockSolCreateAccountsResolve,
+      } = createDeferredPromise();
+      jest
+        .spyOn(solProvider, 'createAccounts')
+        .mockImplementationOnce(() => mockSolCreateAccountsPromise);
 
       // With wait=false (default), only EVM accounts are created immediately.
       const groups = await wallet.createMultichainAccountGroups({ to: 2 });
 
+      // At this point, only EVM provider should have been called to create accounts for groups 1 and 2, but
+      // the SOL provider is has been scheduled, so it shouldn't block.
       expect(groups).toHaveLength(3);
       expect(groups[0].groupIndex).toBe(0); // Existing group.
       expect(groups[1].groupIndex).toBe(1); // New group.
       expect(groups[2].groupIndex).toBe(2); // New group.
       expect(wallet.getAccountGroups()).toHaveLength(3);
 
       // SOL provider is not called during group creation; it's deferred to alignment.
-      expect(solProvider.createAccounts).not.toHaveBeenCalled();
+      mockSolCreateAccountsResolve();
+      await mockSolCreateAccountsPromise;
+      expect(solProvider.createAccounts).toHaveBeenCalled();
     });
 
     it('returns all existing groups when maxGroupIndex is less than nextGroupIndex', async () => {
@@ -575,8 +588,6 @@ describe('MultichainAccountWallet', () => {
         accounts: [[mockEvmAccount0, mockEvmAccount1, mockEvmAccount2]],
       });
 
-      jest.spyOn(wallet, 'alignAccounts').mockResolvedValue(undefined);
-
       // Request groups 0-1 when groups 0-2 exist.
       const groups = await wallet.createMultichainAccountGroups({ to: 1 });