From 844ea25183e340dd742f16e5390da29f1a6a1fa7 Mon Sep 17 00:00:00 2001 From: Elliot DeNolf Date: Sat, 25 Oct 2025 23:04:41 -0400 Subject: [PATCH] feat: perf logging for hooks --- test/_community/collections/Posts/index.ts | 44 ++++++++- test/_community/config.ts | 4 +- .../plugins/hookPerfTesting/index.ts | 67 +++++++++++++ .../plugins/hookPerfTesting/types.ts | 13 +++ .../plugins/hookPerfTesting/utils.ts | 96 +++++++++++++++++++ 5 files changed, 222 insertions(+), 2 deletions(-) create mode 100644 test/_community/plugins/hookPerfTesting/index.ts create mode 100644 test/_community/plugins/hookPerfTesting/types.ts create mode 100644 test/_community/plugins/hookPerfTesting/utils.ts diff --git a/test/_community/collections/Posts/index.ts b/test/_community/collections/Posts/index.ts index 777078b9859..85f9acb9568 100644 --- a/test/_community/collections/Posts/index.ts +++ b/test/_community/collections/Posts/index.ts @@ -7,8 +7,8 @@ export const postsSlug = 'posts' export const PostsCollection: CollectionConfig = { slug: postsSlug, admin: { - useAsTitle: 'title', enableListViewSelectAPI: true, + useAsTitle: 'title', }, fields: [ { @@ -23,4 +23,46 @@ export const PostsCollection: CollectionConfig = { }), }, ], + hooks: { + beforeChange: [ + async ({ data }) => { + // Example hook with random delay between 250-500ms + const delay = Math.floor(Math.random() * 250) + 250 + await new Promise((resolve) => setTimeout(resolve, delay)) + return data + }, + async ({ data }) => { + // Example hook with random delay between 250-500ms + const delay = Math.floor(Math.random() * 250) + 250 + await new Promise((resolve) => setTimeout(resolve, delay)) + return data + }, + async ({ data }) => { + // Example hook with random delay between 250-500ms + const delay = Math.floor(Math.random() * 250) + 250 + await new Promise((resolve) => setTimeout(resolve, delay)) + return data + }, + ], + beforeRead: [ + async ({ doc }) => { + // Example hook with random delay between 250-500ms + const delay = Math.floor(Math.random() * 250) + 250 + await new Promise((resolve) => setTimeout(resolve, delay)) + return doc + }, + async ({ doc }) => { + // Example hook with random delay between 250-500ms + const delay = Math.floor(Math.random() * 250) + 250 + await new Promise((resolve) => setTimeout(resolve, delay)) + return doc + }, + async ({ doc }) => { + // Example hook with random delay between 250-500ms + const delay = Math.floor(Math.random() * 250) + 250 + await new Promise((resolve) => setTimeout(resolve, delay)) + return doc + }, + ], + }, } diff --git a/test/_community/config.ts b/test/_community/config.ts index ee1aee6e46d..cd0808b90db 100644 --- a/test/_community/config.ts +++ b/test/_community/config.ts @@ -7,18 +7,19 @@ import { devUser } from '../credentials.js' import { MediaCollection } from './collections/Media/index.js' import { PostsCollection, postsSlug } from './collections/Posts/index.js' import { MenuGlobal } from './globals/Menu/index.js' +import { hookPerfTestingPlugin } from './plugins/hookPerfTesting/index.js' const filename = fileURLToPath(import.meta.url) const dirname = path.dirname(filename) export default buildConfigWithDefaults({ // ...extend config here - collections: [PostsCollection, MediaCollection], admin: { importMap: { baseDir: path.resolve(dirname), }, }, + collections: [PostsCollection, MediaCollection], editor: lexicalEditor({}), globals: [ // ...add more globals here @@ -40,6 +41,7 @@ export default buildConfigWithDefaults({ }, }) }, + plugins: [hookPerfTestingPlugin()], typescript: { outputFile: path.resolve(dirname, 'payload-types.ts'), }, diff --git a/test/_community/plugins/hookPerfTesting/index.ts b/test/_community/plugins/hookPerfTesting/index.ts new file mode 100644 index 00000000000..569a6448603 --- /dev/null +++ b/test/_community/plugins/hookPerfTesting/index.ts @@ -0,0 +1,67 @@ +import type { CollectionSlug, Plugin } from 'payload' + +import type { HookPerfTestingConfig } from './types.js' + +import { wrapHooksArray } from './utils.js' + +export const hookPerfTestingPlugin = + (pluginConfig?: HookPerfTestingConfig): Plugin => + (config) => { + // Early exit if disabled + if (pluginConfig && pluginConfig.enabled === false) { + return config + } + + const enabledCollections = pluginConfig && pluginConfig.collections + const instrumentAllCollections = !enabledCollections || enabledCollections.length === 0 + + // Modify collections to inject hooks + const collectionsWithHooks = (config.collections || []).map((collection) => { + // Check if this collection should be instrumented + if ( + !instrumentAllCollections && + !enabledCollections.includes(collection.slug as CollectionSlug) + ) { + return collection + } + + const existingHooks = collection.hooks || {} + const slug = collection.slug + + return { + ...collection, + hooks: { + ...existingHooks, + // Lifecycle hooks - wrap existing hooks with timers + afterChange: wrapHooksArray('afterChange', existingHooks.afterChange, slug), + afterDelete: wrapHooksArray('afterDelete', existingHooks.afterDelete, slug), + afterRead: wrapHooksArray('afterRead', existingHooks.afterRead, slug), + beforeChange: wrapHooksArray('beforeChange', existingHooks.beforeChange, slug), + beforeDelete: wrapHooksArray('beforeDelete', existingHooks.beforeDelete, slug), + beforeRead: wrapHooksArray('beforeRead', existingHooks.beforeRead, slug), + beforeValidate: wrapHooksArray('beforeValidate', existingHooks.beforeValidate, slug), + // Operation-wide hooks + afterOperation: wrapHooksArray('afterOperation', existingHooks.afterOperation, slug), + beforeOperation: wrapHooksArray('beforeOperation', existingHooks.beforeOperation, slug), + // Auth hooks (if auth is enabled on the collection) + afterForgotPassword: wrapHooksArray( + 'afterForgotPassword', + existingHooks.afterForgotPassword, + slug, + ), + afterLogin: wrapHooksArray('afterLogin', existingHooks.afterLogin, slug), + afterLogout: wrapHooksArray('afterLogout', existingHooks.afterLogout, slug), + afterMe: wrapHooksArray('afterMe', existingHooks.afterMe, slug), + afterRefresh: wrapHooksArray('afterRefresh', existingHooks.afterRefresh, slug), + beforeLogin: wrapHooksArray('beforeLogin', existingHooks.beforeLogin, slug), + // Error hook + afterError: wrapHooksArray('afterError', existingHooks.afterError, slug), + }, + } + }) + + return { + ...config, + collections: collectionsWithHooks, + } + } diff --git a/test/_community/plugins/hookPerfTesting/types.ts b/test/_community/plugins/hookPerfTesting/types.ts new file mode 100644 index 00000000000..cfa4dd8769a --- /dev/null +++ b/test/_community/plugins/hookPerfTesting/types.ts @@ -0,0 +1,13 @@ +import type { CollectionSlug } from 'payload' + +export type HookPerfTestingConfig = { + /** + * Array of collection slugs to inject performance testing hooks into. + * If not provided, will instrument all collections. + */ + collections?: CollectionSlug[] + /** + * Enable/disable the plugin + */ + enabled?: boolean +} diff --git a/test/_community/plugins/hookPerfTesting/utils.ts b/test/_community/plugins/hookPerfTesting/utils.ts new file mode 100644 index 00000000000..1858ef8a02e --- /dev/null +++ b/test/_community/plugins/hookPerfTesting/utils.ts @@ -0,0 +1,96 @@ +import type { BasePayload, CollectionBeforeChangeHook, PayloadRequest } from 'payload' + +/** + * Wraps a hook with timing logic + * @param hookName - Name of the hook (e.g., 'beforeChange', 'afterRead') + * @param hookFn - Original hook function to wrap + * @param collectionSlug - Collection slug for logging context + * @param hookIndex - Index of hook in array (for multiple hooks of same type) + */ +export function wrapHookWithTimer any>( + hookName: string, + hookFn: T, + collectionSlug: string, + hookIndex: number, +): T { + return (async (...args: Parameters) => { + const startTime = performance.now() + + // Extract req from hook args (first arg is typically the hook args object with req) + const hookArgs = args[0] + const logger = hookArgs?.req?.payload?.logger as BasePayload['logger'] + + try { + const result = await hookFn(...args) + const endTime = performance.now() + const duration = endTime - startTime + + logHookTiming({ + collectionSlug, + duration, + hookIndex, + hookName, + logger, + success: true, + }) + + return result + } catch (error) { + const endTime = performance.now() + const duration = endTime - startTime + + logHookTiming({ + collectionSlug, + duration, + error: error instanceof Error ? error.message : String(error), + hookIndex, + hookName, + logger, + success: false, + }) + + throw error + } + }) as T +} + +type HookTimingLog = { + collectionSlug: string + duration: number + error?: string + hookIndex: number + hookName: string + logger?: BasePayload['logger'] + success: boolean +} + +/** + * Logs hook timing information + */ +function logHookTiming(log: HookTimingLog): void { + const status = log.success ? '✓' : '✗' + const errorMsg = log.error ? ` - Error: ${log.error}` : '' + const message = `[Hook Perf] ${status} ${log.collectionSlug}.${log.hookName}[${log.hookIndex}]: ${Math.round(log.duration)}ms${errorMsg}` + + if (log.logger?.debug) { + log.logger.info(message) + } else { + // Fallback to console if logger not available + console.log(message) + } +} + +/** + * Wraps an array of hooks with timing logic + */ +export function wrapHooksArray any>( + hookName: string, + hooks: T[] | undefined, + collectionSlug: string, +): T[] { + if (!hooks || hooks.length === 0) { + return [] + } + + return hooks.map((hook, index) => wrapHookWithTimer(hookName, hook, collectionSlug, index)) +}