feat(keyring-controller): log mutex and atomic operation timings

packages/keyring-controller/CHANGELOG.md

@@ -9,6 +9,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Added
 
+- Add debug timing logs for controller and vault mutex requests, acquisition, release, and completion, including wait, hold, and total durations; atomic keyring operations are timed separately from their controller-side commit windows ([#11267](https://github.com/MetaMask/core/pull/11267))
+  - Include `keyring: { type, id, kind }`, identifying the underlying keyring and access kind (`v1`, `v2`, or `commit`), in keyring-scoped release/completion logs and atomic operation logs once the entry is selected.
 - Add support for Node.js 26 ([#10981](https://github.com/MetaMask/core/pull/10981))
 - Add atomic keyring builder support: a `KeyringBuilder` can now declare `atomic: true` to receive a `KeyringBuilderContext`, whose `update` callback commits state mutations on the built keyring's behalf — the controller lock is held only for that short commit window, while long-running keyring operations run entirely outside it ([#TODO](https://github.com/MetaMask/core/pull/TODO))
   - The declaration is enforced at the construction choke point: a builder declaring `atomic: true` whose result is not an `AtomicKeyring` (from `@metamask/keyring-sdk`) throws an explicit error.

packages/keyring-controller/README.md

@@ -10,6 +10,39 @@ or
 
 `npm install @metamask/keyring-controller`
 
+## Lock timing diagnostics
+
+Enable `DEBUG=metamask:keyring-controller*` to see lock timing
+logs (using the same project/module logger setup as other controllers).
+
+Each controller or vault mutex acquisition logs `Lock requested`, `Lock acquired`,
+`Lock released`, and `Locked operation finished`, correlated by `id` and labeled
+with the lock and operation names. Durations use a monotonic clock, in milliseconds:
+
+- `waitMs`: time spent waiting to acquire the mutex.
+- `holdMs`: time the mutex was actually held, including transaction setup,
+  persistence, and any rollback.
+- `totalMs`: time from requesting the mutex until the operation finishes.
+- `success`: whether the operation completed without throwing.
+
+For `withKeyring` and `withKeyringV2`, release/completion logs also include
+`keyring: { type, id, kind }`, with kind `v1` or `v2`. The kind describes
+the access path, while the type always identifies the underlying keyring, not
+its V2 adapter. Metadata is added after selection inside the lock, so request
+and acquisition logs do not include it. Wallet-wide operations omit these fields.
+
+Atomic keyrings run their operations outside the controller mutex. Separate
+start/finish logs report their full `durationMs`, while `atomicUpdate` lock logs
+measure only their controller-side commit windows. The keyring's own internal
+lock wait/hold times are not observable by this controller. Atomic operation
+logs include the selected keyring metadata; `atomicUpdate` release/completion
+logs use `keyring.kind: 'commit'`, since commits can originate internally without
+a V1/V2 access path. Rejected updates from detached keyrings omit metadata
+because the registered entry no longer exists. Unsafe read-only
+operations do not acquire a mutex and do not produce lock timing logs.
+
+Logs omit operation arguments, results, and errors to avoid exposing secrets.
+
 ## Contributing
 
 This package is part of a monorepo. Instructions for contributing can be found in the [monorepo README](https://github.com/MetaMask/core#readme).

packages/keyring-controller/src/KeyringController.test.ts

@@ -66,6 +66,9 @@ import {
   isCustodyKeyring,
   keyringBuilderFactory,
 } from './KeyringController.js';
+import { lockLogger, projectLogger } from './logger.js';
+
+vi.mock('./logger.js', () => ({ lockLogger: vi.fn(), projectLogger: vi.fn() }));
 
 type AllKeyringControllerActions = MessengerActions<KeyringControllerMessenger>;
 
@@ -4133,6 +4136,19 @@ describe('KeyringController', () => {
           'Oops',
         );
 
+        expect(lockLogger).toHaveBeenLastCalledWith(
+          'Locked operation finished',
+          expect.objectContaining({
+            operation: 'withKeyring',
+            keyring: {
+              type: KeyringTypes.hd,
+              kind: 'v1',
+              id: initialState.keyrings[0].metadata.id,
+            },
+            success: false,
+          }),
+        );
+
         expect(controller.state.keyrings[0].accounts).toHaveLength(1);
         expect(await controller.getAccounts()).toStrictEqual(
           initialState.keyrings[0].accounts,
@@ -5147,6 +5163,17 @@ describe('KeyringController', () => {
             metadata: expect.objectContaining({ id: expect.any(String) }),
           }),
         );
+        expect(lockLogger).toHaveBeenCalledWith(
+          'Locked operation finished',
+          expect.objectContaining({
+            operation: 'withKeyringV2',
+            keyring: {
+              type: KeyringTypes.hd,
+              kind: 'v2',
+              id: controller.state.keyrings[0].metadata.id,
+            },
+          }),
+        );
       });
     });
 
@@ -8107,6 +8134,8 @@ describe('KeyringController atomic keyring support', () => {
       { keyringBuilders: [buildFakeAtomicKeyringBuilder(remote)] },
       async ({ controller }) => {
         await controller.addNewKeyring(ATOMIC_TEST_KEYRING_TYPE);
+        vi.mocked(lockLogger).mockClear();
+        vi.mocked(projectLogger).mockClear();
         const fake = controller.getKeyringsByType(
           ATOMIC_TEST_KEYRING_TYPE,
         )[0] as FakeAtomicKeyring;
@@ -8136,10 +8165,70 @@ describe('KeyringController atomic keyring support', () => {
           expect(fake.state.status).toBe('uninitialized');
         });
 
+        expect(projectLogger).toHaveBeenCalledWith(
+          'Atomic keyring operation started (outside controller lock)',
+          {
+            id: expect.any(Number),
+            operation: 'withKeyring',
+            keyring: {
+              type: ATOMIC_TEST_KEYRING_TYPE,
+              kind: 'v1',
+              id: controller.state.keyrings.find(
+                ({ type }) => type === ATOMIC_TEST_KEYRING_TYPE,
+              )?.metadata.id,
+            },
+          },
+        );
+        expect(projectLogger).toHaveBeenCalledTimes(1);
+        expect(lockLogger).toHaveBeenCalledWith(
+          'Locked operation finished',
+          expect.objectContaining({
+            operation: 'withKeyring',
+            success: true,
+            keyring: {
+              type: ATOMIC_TEST_KEYRING_TYPE,
+              kind: 'v1',
+              id: expect.any(String),
+            },
+          }),
+        );
+        expect(lockLogger).not.toHaveBeenCalledWith(
+          'Lock requested',
+          expect.objectContaining({ operation: 'atomicUpdate' }),
+        );
+
         ceremonyGate.resolve();
         await operation;
 
         expect(fake.state.status).toBe('ready');
+        expect(lockLogger).toHaveBeenCalledWith(
+          'Locked operation finished',
+          expect.objectContaining({
+            operation: 'atomicUpdate',
+            keyring: {
+              type: ATOMIC_TEST_KEYRING_TYPE,
+              kind: 'commit',
+              id: expect.any(String),
+            },
+          }),
+        );
+        expect(projectLogger).toHaveBeenLastCalledWith(
+          'Atomic keyring operation finished (outside controller lock)',
+          expect.objectContaining({
+            operation: 'withKeyring',
+            durationMs: expect.any(Number),
+            success: true,
+          }),
+        );
+        expect(
+          vi
+            .mocked(lockLogger)
+            .mock.calls.filter(([message]) => message === 'Lock acquired')
+            .filter(
+              ([, details]) =>
+                (details as { operation: string }).operation === 'atomicUpdate',
+            ),
+        ).toHaveLength(2);
       },
     );
   });
@@ -8170,6 +8259,14 @@ describe('KeyringController atomic keyring support', () => {
           ),
         ).rejects.toThrow('activation failed');
 
+        expect(projectLogger).toHaveBeenLastCalledWith(
+          'Atomic keyring operation finished (outside controller lock)',
+          expect.objectContaining({
+            success: false,
+            durationMs: expect.any(Number),
+          }),
+        );
+
         // The staged update survived the operation error: there is no
         // rollback for atomic keyrings.
         expect(fake.state.status).toBe('staged');