diff --git a/lib/experimental/sync/class-gutenberg-http-polling-sync-server.php b/lib/experimental/sync/class-gutenberg-http-polling-sync-server.php index c59ddeb409d490..389b56b597b815 100644 --- a/lib/experimental/sync/class-gutenberg-http-polling-sync-server.php +++ b/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, diff --git a/packages/core-data/src/resolvers.js b/packages/core-data/src/resolvers.js index bf77698208eda1..ba69d1b4eb0227 100644 --- a/packages/core-data/src/resolvers.js +++ b/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, diff --git a/packages/sync/src/manager.ts b/packages/sync/src/manager.ts index c9341706e53496..cc05a6597af9a7 100644 --- a/packages/sync/src/manager.ts +++ b/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 ) ), }; } diff --git a/packages/sync/src/performance.ts b/packages/sync/src/performance.ts new file mode 100644 index 00000000000000..e93f87ee031b55 --- /dev/null +++ b/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 ); + }; +} diff --git a/packages/sync/src/test/manager.ts b/packages/sync/src/test/manager.ts index 45e354d7ff8544..2d0e5fdacce4d8 100644 --- a/packages/sync/src/test/manager.ts +++ b/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 ), diff --git a/packages/sync/src/test/performance.test.ts b/packages/sync/src/test/performance.test.ts new file mode 100644 index 00000000000000..b259050eec5bb4 --- /dev/null +++ b/packages/sync/src/test/performance.test.ts @@ -0,0 +1,286 @@ +/** + * External dependencies + */ +import { + describe, + expect, + it, + jest, + beforeEach, + afterEach, +} from '@jest/globals'; + +/** + * Internal dependencies + */ +import { + logPerformanceTiming, + passThru, + yieldToEventLoop, +} from '../performance'; + +describe( 'performance utilities', () => { + describe( 'logPerformanceTiming', () => { + let consoleSpy: jest.SpiedFunction< typeof console.log >; + + beforeEach( () => { + consoleSpy = jest + .spyOn( console, 'log' ) + .mockImplementation( () => {} ); + } ); + + afterEach( () => { + consoleSpy.mockRestore(); + } ); + + it( 'calls the wrapped function and returns its result', () => { + function add( a: number, b: number ): number { + return a + b; + } + + const wrapped = logPerformanceTiming( add ); + const result = wrapped( 2, 3 ); + + expect( result ).toBe( 5 ); + } ); + + it( 'logs the function name and execution time', () => { + function myFunction(): void {} + + const wrapped = logPerformanceTiming( myFunction ); + wrapped(); + + expect( consoleSpy ).toHaveBeenCalledTimes( 1 ); + expect( consoleSpy.mock.calls[ 0 ][ 0 ] ).toMatch( + /^myFunction took \d+\.\d{2} ms$/ + ); + } ); + + it( 'passes all arguments to the wrapped function', () => { + const fn = jest.fn( ( a: number, b: string, c: boolean ) => { + return `${ a }-${ b }-${ c }`; + } ); + + const wrapped = logPerformanceTiming( fn ); + const result = wrapped( 42, 'test', true ); + + expect( fn ).toHaveBeenCalledWith( 42, 'test', true ); + expect( result ).toBe( '42-test-true' ); + } ); + + it( 'preserves the this context', () => { + const obj = { + value: 10, + getValue( this: { value: number } ): number { + return this.value; + }, + }; + + const wrapped = logPerformanceTiming( obj.getValue ); + const result = wrapped.call( obj ); + + expect( result ).toBe( 10 ); + } ); + + it( 'handles functions that throw errors', () => { + function throwError(): never { + throw new Error( 'test error' ); + } + + const wrapped = logPerformanceTiming( throwError ); + + expect( () => wrapped() ).toThrow( 'test error' ); + } ); + + it( 'handles functions with no return value', () => { + let sideEffect = 0; + function incrementSideEffect(): void { + sideEffect += 1; + } + + const wrapped = logPerformanceTiming( incrementSideEffect ); + const result = wrapped(); + + expect( result ).toBeUndefined(); + expect( sideEffect ).toBe( 1 ); + } ); + + it( 'handles anonymous functions', () => { + const wrapped = logPerformanceTiming( () => 'result' ); + const result = wrapped(); + + expect( result ).toBe( 'result' ); + expect( consoleSpy ).toHaveBeenCalledTimes( 1 ); + } ); + } ); + + describe( 'passThru', () => { + it( 'returns a function that calls the original function', () => { + const fn = jest.fn( () => 'result' ); + + const wrapped = passThru( fn ); + const result = wrapped(); + + expect( fn ).toHaveBeenCalledTimes( 1 ); + expect( result ).toBe( 'result' ); + } ); + + it( 'passes all arguments to the original function', () => { + const fn = jest.fn( ( a: number, b: string ) => `${ a }-${ b }` ); + + const wrapped = passThru( fn ); + const result = wrapped( 42, 'test' ); + + expect( fn ).toHaveBeenCalledWith( 42, 'test' ); + expect( result ).toBe( '42-test' ); + } ); + + it( 'preserves the function return type', () => { + function getNumber(): number { + return 42; + } + + const wrapped = passThru( getNumber ); + const result: number = wrapped(); + + expect( result ).toBe( 42 ); + } ); + + it( 'handles functions with rest parameters', () => { + const sum = ( ...numbers: number[] ): number => + numbers.reduce( ( a, b ) => a + b, 0 ); + + const wrapped = passThru( sum ); + const result = wrapped( 1, 2, 3, 4, 5 ); + + expect( result ).toBe( 15 ); + } ); + + it( 'handles async functions', async () => { + const asyncFn = async ( value: string ): Promise< string > => { + return `async-${ value }`; + }; + + const wrapped = passThru( asyncFn ); + const result = await wrapped( 'test' ); + + expect( result ).toBe( 'async-test' ); + } ); + + it( 'handles functions that throw errors', () => { + const fn = (): never => { + throw new Error( 'test error' ); + }; + + const wrapped = passThru( fn ); + + expect( () => wrapped() ).toThrow( 'test error' ); + } ); + } ); + + describe( 'yieldToEventLoop', () => { + beforeEach( () => { + jest.useFakeTimers(); + } ); + + afterEach( () => { + jest.useRealTimers(); + } ); + + it( 'delays function execution to the next tick', () => { + const fn = jest.fn(); + + const wrapped = yieldToEventLoop( fn ); + wrapped(); + + expect( fn ).not.toHaveBeenCalled(); + + jest.runAllTimers(); + + expect( fn ).toHaveBeenCalledTimes( 1 ); + } ); + + it( 'passes all arguments to the wrapped function', () => { + const fn = jest.fn( ( a: number, b: string ) => `${ a }-${ b }` ); + + const wrapped = yieldToEventLoop( fn ); + wrapped( 42, 'test' ); + + jest.runAllTimers(); + + expect( fn ).toHaveBeenCalledWith( 42, 'test' ); + } ); + + it( 'preserves the this context', () => { + const obj = { + value: 10, + logValue: jest.fn( function ( this: { value: number } ) { + return this.value; + } ), + }; + + const wrapped = yieldToEventLoop( obj.logValue ); + wrapped.call( obj ); + + jest.runAllTimers(); + + expect( obj.logValue ).toHaveBeenCalled(); + expect( obj.logValue.mock.instances[ 0 ] ).toBe( obj ); + } ); + + it( 'handles multiple invocations', () => { + const fn = jest.fn(); + + const wrapped = yieldToEventLoop( fn ); + wrapped(); + wrapped(); + wrapped(); + + expect( fn ).not.toHaveBeenCalled(); + + jest.runAllTimers(); + + expect( fn ).toHaveBeenCalledTimes( 3 ); + } ); + + it( 'each invocation is independent', () => { + const calls: number[] = []; + const fn = ( value: number ): void => { + calls.push( value ); + }; + + const wrapped = yieldToEventLoop( fn ); + wrapped( 1 ); + wrapped( 2 ); + wrapped( 3 ); + + jest.runAllTimers(); + + expect( calls ).toEqual( [ 1, 2, 3 ] ); + } ); + + it( 'uses setTimeout with 0ms delay', () => { + const setTimeoutSpy = jest.spyOn( global, 'setTimeout' ); + const fn = jest.fn(); + + const wrapped = yieldToEventLoop( fn ); + wrapped(); + + expect( setTimeoutSpy ).toHaveBeenCalledWith( + expect.any( Function ), + 0 + ); + + setTimeoutSpy.mockRestore(); + } ); + + it( 'returns void', () => { + const fn = jest.fn( () => 'result' ); + + const wrapped = yieldToEventLoop( fn as () => void ); + const result = wrapped(); + + expect( result ).toBeUndefined(); + } ); + } ); +} );