feat: perf logging for hooks

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
+      },
+    ],
+  },
 }

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'),
   },

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,
+    }
+  }

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
+}

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<T extends (...args: any[]) => any>(
+  hookName: string,
+  hookFn: T,
+  collectionSlug: string,
+  hookIndex: number,
+): T {
+  return (async (...args: Parameters<T>) => {
+    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<T extends (...args: any[]) => 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))
+}