test: add browse instrumentation helpers

server/utils/profiler.js

@@ -4,6 +4,18 @@ const Logger = require('../Logger')
 
 const histograms = new Map()
 
+function createRequestScopedFindOptions(findOptions, funcName) {
+  if (!findOptions || typeof findOptions !== 'object' || Array.isArray(findOptions)) {
+    return findOptions
+  }
+
+  return {
+    ...findOptions,
+    logging: (query, time) => Logger.info(`[${funcName}] ${query} Elapsed time: ${time}ms`),
+    benchmark: true
+  }
+}
+
 function profile(asyncFunc, isFindQuery = true, funcName = asyncFunc.name) {
   if (!histograms.has(funcName)) {
     const histogram = createHistogram()
@@ -13,15 +25,15 @@ function profile(asyncFunc, isFindQuery = true, funcName = asyncFunc.name) {
   const histogram = histograms.get(funcName)
 
   return async (...args) => {
+    const requestArgs = isFindQuery ? [createRequestScopedFindOptions(args[0], funcName), ...args.slice(1)] : args
+
     if (isFindQuery) {
-      const findOptions = args[0]
+      const findOptions = requestArgs[0]
       Logger.info(`[${funcName}] findOptions:`, util.inspect(findOptions, { depth: null }))
-      findOptions.logging = (query, time) => Logger.info(`[${funcName}] ${query} Elapsed time: ${time}ms`)
-      findOptions.benchmark = true
     }
     const start = performance.now()
     try {
-      const result = await asyncFunc(...args)
+      const result = await asyncFunc(...requestArgs)
       return result
     } catch (error) {
       Logger.error(`[${funcName}] failed`)

server/utils/queries/libraryBrowseInstrumentation.js

@@ -0,0 +1,57 @@
+const { performance } = require('perf_hooks')
+
+function getPhaseName(markName) {
+  return String(markName || '').split(':')[0]
+}
+
+function createBrowseRequestProfile(context = {}) {
+  const now = typeof context.now === 'function' ? context.now : () => performance.now()
+  const marks = []
+
+  return {
+    route: context.route || null,
+    libraryId: context.libraryId || null,
+    now,
+    startedAt: now(),
+    marks,
+    mark(name) {
+      marks.push({ name, at: now() })
+    }
+  }
+}
+
+function finishBrowseRequestProfile(profile, { slowMs = 1000 } = {}) {
+  const endedAt = profile.now()
+  const phases = {}
+  const openPhases = new Map()
+
+  profile.marks.forEach((mark) => {
+    const phaseName = getPhaseName(mark.name)
+    if (!phaseName) return
+
+    if (String(mark.name).endsWith(':start')) {
+      openPhases.set(phaseName, mark.at)
+      return
+    }
+
+    if (String(mark.name).endsWith(':end') && openPhases.has(phaseName)) {
+      phases[phaseName] = Math.round(mark.at - openPhases.get(phaseName))
+      openPhases.delete(phaseName)
+    }
+  })
+
+  const totalMs = Math.round(endedAt - profile.startedAt)
+
+  return {
+    route: profile.route || null,
+    libraryId: profile.libraryId || null,
+    totalMs,
+    phases,
+    isSlow: totalMs >= slowMs
+  }
+}
+
+module.exports = {
+  createBrowseRequestProfile,
+  finishBrowseRequestProfile
+}

test/server/utils/libraryBrowseInstrumentation.test.js

@@ -0,0 +1,54 @@
+const chai = require('chai')
+const expect = chai.expect
+
+const {
+  createBrowseRequestProfile,
+  finishBrowseRequestProfile
+} = require('../../../server/utils/queries/libraryBrowseInstrumentation')
+
+describe('libraryBrowseInstrumentation', () => {
+  it('records named browse phases and returns a slow-summary payload', () => {
+    const timestamps = [
+      100,
+      110,
+      160,
+      170,
+      200,
+      210,
+      235,
+      240,
+      280,
+      320
+    ]
+
+    const profile = createBrowseRequestProfile({
+      route: 'GET /api/libraries/:id/items',
+      libraryId: 'lib_1',
+      now: () => timestamps.shift()
+    })
+
+    profile.mark('rows:start')
+    profile.mark('rows:end')
+    profile.mark('count:start')
+    profile.mark('count:end')
+    profile.mark('derived:start')
+    profile.mark('derived:end')
+    profile.mark('postprocess:start')
+    profile.mark('postprocess:end')
+
+    const result = finishBrowseRequestProfile(profile, { slowMs: 150 })
+
+    expect(result).to.deep.equal({
+      route: 'GET /api/libraries/:id/items',
+      libraryId: 'lib_1',
+      totalMs: 220,
+      phases: {
+        rows: 50,
+        count: 30,
+        derived: 25,
+        postprocess: 40
+      },
+      isSlow: true
+    })
+  })
+})