Improve sync performance metrics (#75029)

* Add a "debug" mode to expose performance timing of sync functions

* Yield to event loop before updating CRDT document

* Do not await promise when loading entity for syncing

* Add tests for new performance functions

* Add missing `type` option for REST API endoint

* Remove debugWrap of getAwareness (generics)

Author: chriszarate

lib/experimental/sync/class-gutenberg-http-polling-sync-server.php

@@ -87,6 +87,7 @@ public function register_routes(): void {
 			),
 			'awareness' => array(
 				'required' => true,
+				'type'     => 'object',
 			),
 			'client_id' => array(
 				'minimum'  => 1,

packages/core-data/src/resolvers.js

@@ -185,8 +185,8 @@ export const getEntityRecord =
 								transientConfig.read( recordWithTransients );
 						} );
 
-					// Load the entity record for syncing.
-					await getSyncManager()?.load(
+					// Load the entity record for syncing. Do not await promise.
+					void getSyncManager()?.load(
 						entityConfig.syncConfig,
 						objectType,
 						objectId,

packages/sync/src/manager.ts

@@ -13,6 +13,11 @@ import {
 	CRDT_RECORD_METADATA_MAP_KEY as RECORD_METADATA_KEY,
 	CRDT_RECORD_METADATA_SAVED_AT_KEY as SAVED_AT_KEY,
 } from './config';
+import {
+	logPerformanceTiming,
+	passThru,
+	yieldToEventLoop,
+} from './performance';
 import { createPersistedCRDTDoc, getPersistedCrdtDoc } from './persistence';
 import { getProviderCreators } from './providers';
 import type {
@@ -50,12 +55,28 @@ interface EntityState {
 	ydoc: CRDTDoc;
 }
 
+/**
+ * Get the entity ID for the given object type and object ID.
+ *
+ * @param {ObjectType}    objectType Object type.
+ * @param {ObjectID|null} objectId   Object ID.
+ */
+function getEntityId(
+	objectType: ObjectType,
+	objectId: ObjectID | null
+): EntityID {
+	return `${ objectType }_${ objectId }`;
+}
+
 /**
  * The sync manager orchestrates the lifecycle of syncing entity records. It
  * creates Yjs documents, connects to providers, creates awareness instances,
  * and coordinates with the `core-data` store.
+ *
+ * @param debug Whether to enable performance and debug logging.
  */
-export function createSyncManager(): SyncManager {
+export function createSyncManager( debug = false ): SyncManager {
+	const debugWrap = debug ? logPerformanceTiming : passThru;
 	const collectionStates: Map< ObjectType, CollectionState > = new Map();
 	const entityStates: Map< EntityID, EntityState > = new Map();
 
@@ -118,6 +139,15 @@ export function createSyncManager(): SyncManager {
 			return; // Already bootstrapped.
 		}
 
+		handlers = {
+			addUndoMeta: debugWrap( handlers.addUndoMeta ),
+			editRecord: debugWrap( handlers.editRecord ),
+			getEditedRecord: debugWrap( handlers.getEditedRecord ),
+			refetchRecord: debugWrap( handlers.refetchRecord ),
+			restoreUndoMeta: debugWrap( handlers.restoreUndoMeta ),
+			saveRecord: debugWrap( handlers.saveRecord ),
+		};
+
 		const ydoc = createYjsDoc( { objectType } );
 		const recordMap = ydoc.getMap( RECORD_KEY );
 		const recordMetaMap = ydoc.getMap( RECORD_METADATA_KEY );
@@ -148,7 +178,7 @@ export function createSyncManager(): SyncManager {
 				return;
 			}
 
-			void updateEntityRecord( objectType, objectId );
+			void internal.updateEntityRecord( objectType, objectId );
 		};
 
 		const onRecordMetaUpdate = (
@@ -208,7 +238,7 @@ export function createSyncManager(): SyncManager {
 		recordMetaMap.observe( onRecordMetaUpdate );
 
 		// Get and apply the persisted CRDT document, if it exists.
-		applyPersistedCrdtDoc( objectType, objectId, record );
+		internal.applyPersistedCrdtDoc( objectType, objectId, record );
 	}
 
 	/**
@@ -308,19 +338,6 @@ export function createSyncManager(): SyncManager {
 		updateCRDTDoc( objectType, null, {}, origin, { isSave: true } );
 	}
 
-	/**
-	 * Get the entity ID for the given object type and object ID.
-	 *
-	 * @param {ObjectType}    objectType Object type.
-	 * @param {ObjectID|null} objectId   Object ID.
-	 */
-	function getEntityId(
-		objectType: ObjectType,
-		objectId: ObjectID | null
-	): EntityID {
-		return `${ objectType }_${ objectId }`;
-	}
-
 	/**
 	 * Get the awareness instance for the given object type and object ID, if supported.
 	 *
@@ -352,7 +369,7 @@ export function createSyncManager(): SyncManager {
 	 * @param {ObjectID}   objectId   Object ID.
 	 * @param {ObjectData} record     Entity record representing this object type.
 	 */
-	function applyPersistedCrdtDoc(
+	function _applyPersistedCrdtDoc(
 		objectType: ObjectType,
 		objectId: ObjectID,
 		record: ObjectData
@@ -505,7 +522,7 @@ export function createSyncManager(): SyncManager {
 	 * @param {ObjectType} objectType Object type of record to update.
 	 * @param {ObjectID}   objectId   Object ID of record to update.
 	 */
-	async function updateEntityRecord(
+	async function _updateEntityRecord(
 		objectType: ObjectType,
 		objectId: ObjectID
 	): Promise< void > {
@@ -556,16 +573,23 @@ export function createSyncManager(): SyncManager {
 		return createPersistedCRDTDoc( entityState.ydoc );
 	}
 
+	// Collect internal functions so that they can be wrapped before calling.
+	const internal = {
+		applyPersistedCrdtDoc: debugWrap( _applyPersistedCrdtDoc ),
+		updateEntityRecord: debugWrap( _updateEntityRecord ),
+	};
+
+	// Wrap and return the public API.
 	return {
-		createMeta: createEntityMeta,
+		createMeta: debugWrap( createEntityMeta ),
 		getAwareness,
-		load: loadEntity,
-		loadCollection,
+		load: debugWrap( loadEntity ),
+		loadCollection: debugWrap( loadCollection ),
 		// Use getter to ensure we always return the current value of `undoManager`.
 		get undoManager(): SyncUndoManager | undefined {
 			return undoManager;
 		},
-		unload: unloadEntity,
-		update: updateCRDTDoc,
+		unload: debugWrap( unloadEntity ),
+		update: debugWrap( yieldToEventLoop( updateCRDTDoc ) ),
 	};
 }

packages/sync/src/performance.ts

@@ -0,0 +1,47 @@
+/**
+ * Wraps a function and logs the time it takes to execute.
+ *
+ * @param fn - The function to be wrapped.
+ */
+export function logPerformanceTiming<
+	Params extends Array< unknown >,
+	ReturnType = void,
+>( fn: ( ...args: Params ) => ReturnType ): typeof fn {
+	return function ( this: unknown, ...args: Params ): ReturnType {
+		const start = performance.now();
+		const result = fn.apply( this, args );
+		const end = performance.now();
+
+		// eslint-disable-next-line no-console
+		console.log( `${ fn.name } took ${ ( end - start ).toFixed( 2 ) } ms` );
+
+		return result;
+	};
+}
+
+/**
+ * A pass-through function that invokes the provided function with its arguments
+ * without moidyfing its type.
+ *
+ * @param fn - The function to be invoked.
+ */
+export function passThru< T extends ( ...args: any[] ) => any >( fn: T ): T {
+	return ( ( ...args: Parameters< T > ): ReturnType< T > =>
+		fn( ...args ) ) as T;
+}
+
+/**
+ * Wraps a function so that every invocation is delayed until the next tick of
+ * the event loop.
+ *
+ * @param fn - The function to be scheduled.
+ */
+export function yieldToEventLoop< Params extends Array< unknown > >(
+	fn: ( ...args: Params ) => void
+): typeof fn {
+	return function ( this: unknown, ...args: Params ): void {
+		setTimeout( () => {
+			fn.apply( this, args );
+		}, 0 );
+	};
+}

packages/sync/src/test/manager.ts

@@ -480,6 +480,9 @@ describe( 'SyncManager', () => {
 			jest.clearAllMocks();
 			manager.update( 'post', '456', { title: 'Updated' }, 'local' );
 
+			// Wait a tick for yieldToEventLoop.
+			await new Promise( ( resolve ) => setTimeout( resolve, 0 ) );
+
 			expect( mockSyncConfig.applyChangesToCRDTDoc ).toHaveBeenCalled();
 		} );
 	} );
@@ -508,6 +511,9 @@ describe( 'SyncManager', () => {
 			const changes = { title: 'Updated Title' };
 			manager.update( 'post', '123', changes, 'local-editor' );
 
+			// Wait a tick for yieldToEventLoop.
+			await new Promise( ( resolve ) => setTimeout( resolve, 0 ) );
+
 			// Verify that applyChangesToCRDTDoc was called with the changes.
 			expect( mockSyncConfig.applyChangesToCRDTDoc ).toHaveBeenCalledWith(
 				expect.any( Y.Doc ),
@@ -521,12 +527,15 @@ describe( 'SyncManager', () => {
 			expect( metadataMap.get( SAVED_BY_KEY ) ).toBeUndefined();
 		} );
 
-		it( 'does not update when entity is not loaded', () => {
+		it( 'does not update when entity is not loaded', async () => {
 			const manager = createSyncManager();
 
 			const changes = { title: 'Updated Title' };
 			manager.update( 'post', '999', changes, 'local-editor' );
 
+			// Wait a tick for yieldToEventLoop.
+			await new Promise( ( resolve ) => setTimeout( resolve, 0 ) );
+
 			expect(
 				mockSyncConfig.applyChangesToCRDTDoc
 			).not.toHaveBeenCalled();
@@ -564,6 +573,9 @@ describe( 'SyncManager', () => {
 
 			manager.update( 'post', '123', changes, customOrigin );
 
+			// Wait a tick for yieldToEventLoop.
+			await new Promise( ( resolve ) => setTimeout( resolve, 0 ) );
+
 			expect( transactSpy ).toHaveBeenCalledWith(
 				expect.any( Function ),
 				customOrigin
@@ -597,6 +609,9 @@ describe( 'SyncManager', () => {
 				isSave: true,
 			} );
 
+			// Wait a tick for yieldToEventLoop.
+			await new Promise( ( resolve ) => setTimeout( resolve, 0 ) );
+
 			// Verify that applyChangesToCRDTDoc was called with the changes.
 			expect( mockSyncConfig.applyChangesToCRDTDoc ).toHaveBeenCalledWith(
 				expect.any( Y.Doc ),