fix: wire browse request timing hooks

server/utils/profiler.js

@@ -4,15 +4,40 @@ const Logger = require('../Logger')
 
 const histograms = new Map()
 
-function createRequestScopedFindOptions(findOptions, funcName) {
-  if (!findOptions || typeof findOptions !== 'object' || Array.isArray(findOptions)) {
-    return findOptions
+function callTimingHook(requestTiming, hookName, ...args) {
+  if (!requestTiming || typeof requestTiming[hookName] !== 'function') return
+  requestTiming[hookName](...args)
+}
+
+function createRequestScopedLogging(funcName, logging, requestTiming) {
+  const logger = (...args) => {
+    Logger.info(`[${funcName}] ${args[0]} Elapsed time: ${args[1]}ms`)
+    if (typeof logging === 'function') {
+      logging(...args)
+    }
+    callTimingHook(requestTiming, 'onQuery', ...args)
   }
 
+  return logger
+}
+
+function createRequestScopedFindOptions(findOptions, funcName) {
+  if (!findOptions || typeof findOptions !== 'object' || Array.isArray(findOptions)) {
+    return {
+      findOptions,
+      requestTiming: null
+    }
+  }
+
+  const requestTiming = findOptions.requestTiming || null
+
   return {
-    ...findOptions,
-    logging: (query, time) => Logger.info(`[${funcName}] ${query} Elapsed time: ${time}ms`),
-    benchmark: true
+    requestTiming,
+    findOptions: {
+      ...findOptions,
+      logging: createRequestScopedLogging(funcName, findOptions.logging, requestTiming),
+      benchmark: true
+    }
   }
 }
 
@@ -25,22 +50,26 @@ 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
+    const requestScoped = isFindQuery ? createRequestScopedFindOptions(args[0], funcName) : { findOptions: args[0], requestTiming: null }
+    const requestArgs = isFindQuery ? [requestScoped.findOptions, ...args.slice(1)] : args
 
     if (isFindQuery) {
       const findOptions = requestArgs[0]
       Logger.info(`[${funcName}] findOptions:`, util.inspect(findOptions, { depth: null }))
     }
     const start = performance.now()
+    callTimingHook(requestScoped.requestTiming, 'onStart', requestArgs[0])
     try {
       const result = await asyncFunc(...requestArgs)
+      callTimingHook(requestScoped.requestTiming, 'onFinish', result)
       return result
     } catch (error) {
       Logger.error(`[${funcName}] failed`)
+      callTimingHook(requestScoped.requestTiming, 'onError', error)
       throw error
     } finally {
       const end = performance.now()
-      const duration = Math.round(end - start)
+      const duration = Math.max(1, Math.round(end - start))
       histogram.record(duration)
       histogram.values.push(duration)
       Logger.info(`[${funcName}] duration: ${duration}ms`)

server/utils/queries/libraryBrowseInstrumentation.js

@@ -4,6 +4,24 @@ function getPhaseName(markName) {
   return String(markName || '').split(':')[0]
 }
 
+function createBrowsePhaseTiming(profile, phaseName) {
+  if (!profile || typeof profile.mark !== 'function' || !phaseName) {
+    return null
+  }
+
+  return {
+    onStart() {
+      profile.mark(`${phaseName}:start`)
+    },
+    onFinish() {
+      profile.mark(`${phaseName}:end`)
+    },
+    onError() {
+      profile.mark(`${phaseName}:end`)
+    }
+  }
+}
+
 function createBrowseRequestProfile(context = {}) {
   const now = typeof context.now === 'function' ? context.now : () => performance.now()
   const marks = []
@@ -21,11 +39,24 @@ function createBrowseRequestProfile(context = {}) {
 }
 
 function finishBrowseRequestProfile(profile, { slowMs = 1000 } = {}) {
-  const endedAt = profile.now()
+  if (!profile || typeof profile !== 'object') {
+    return {
+      route: null,
+      libraryId: null,
+      totalMs: 0,
+      phases: {},
+      isSlow: false
+    }
+  }
+
+  const now = typeof profile.now === 'function' ? profile.now : () => performance.now()
+  const startedAt = typeof profile.startedAt === 'number' ? profile.startedAt : null
+  const marks = Array.isArray(profile.marks) ? profile.marks : []
+  const endedAt = startedAt === null ? null : now()
   const phases = {}
   const openPhases = new Map()
 
-  profile.marks.forEach((mark) => {
+  marks.forEach((mark) => {
     const phaseName = getPhaseName(mark.name)
     if (!phaseName) return
 
@@ -35,23 +66,24 @@ function finishBrowseRequestProfile(profile, { slowMs = 1000 } = {}) {
     }
 
     if (String(mark.name).endsWith(':end') && openPhases.has(phaseName)) {
-      phases[phaseName] = Math.round(mark.at - openPhases.get(phaseName))
+      phases[phaseName] = (phases[phaseName] || 0) + Math.round(mark.at - openPhases.get(phaseName))
       openPhases.delete(phaseName)
     }
   })
 
-  const totalMs = Math.round(endedAt - profile.startedAt)
+  const totalMs = endedAt === null ? 0 : Math.round(endedAt - startedAt)
 
   return {
     route: profile.route || null,
     libraryId: profile.libraryId || null,
     totalMs,
     phases,
-    isSlow: totalMs >= slowMs
+    isSlow: totalMs > 0 && totalMs >= slowMs
   }
 }
 
 module.exports = {
+  createBrowsePhaseTiming,
   createBrowseRequestProfile,
   finishBrowseRequestProfile
 }

test/server/utils/libraryBrowseInstrumentation.test.js

@@ -1,12 +1,19 @@
 const chai = require('chai')
 const expect = chai.expect
+const sinon = require('sinon')
 
 const {
   createBrowseRequestProfile,
+  createBrowsePhaseTiming,
   finishBrowseRequestProfile
 } = require('../../../server/utils/queries/libraryBrowseInstrumentation')
+const { profile } = require('../../../server/utils/profiler')
 
 describe('libraryBrowseInstrumentation', () => {
+  afterEach(() => {
+    sinon.restore()
+  })
+
   it('records named browse phases and returns a slow-summary payload', () => {
     const timestamps = [
       100,
@@ -51,4 +58,69 @@ describe('libraryBrowseInstrumentation', () => {
       isSlow: true
     })
   })
+
+  it('accumulates repeated timings for the same phase', () => {
+    const timestamps = [100, 110, 140, 150, 190, 210]
+    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('rows:start')
+    profile.mark('rows:end')
+
+    const result = finishBrowseRequestProfile(profile, { slowMs: 500 })
+
+    expect(result.phases).to.deep.equal({ rows: 70 })
+    expect(result.isSlow).to.equal(false)
+  })
+
+  it('handles null and partial profiles safely', () => {
+    expect(finishBrowseRequestProfile(null, { slowMs: 0 })).to.deep.equal({
+      route: null,
+      libraryId: null,
+      totalMs: 0,
+      phases: {},
+      isSlow: false
+    })
+
+    expect(finishBrowseRequestProfile({ route: 'GET /items', marks: [{ name: 'rows:start', at: 10 }] })).to.deep.equal({
+      route: 'GET /items',
+      libraryId: null,
+      totalMs: 0,
+      phases: {},
+      isSlow: false
+    })
+  })
+
+  it('composes caller logging with request-scoped browse timing hooks', async () => {
+    const timestamps = [100, 110, 150, 180]
+    const browseProfile = createBrowseRequestProfile({
+      route: 'GET /api/libraries/:id/items',
+      libraryId: 'lib_1',
+      now: () => timestamps.shift()
+    })
+    const callerLogging = sinon.spy()
+    const originalFindOptions = {
+      where: { id: 'item_1' },
+      logging: callerLogging,
+      requestTiming: createBrowsePhaseTiming(browseProfile, 'rows')
+    }
+
+    const wrappedQuery = profile(async (findOptions) => {
+      findOptions.logging('SELECT 1', 12)
+      return findOptions
+    }, true, 'browseRows')
+
+    const wrappedFindOptions = await wrappedQuery(originalFindOptions)
+    const result = finishBrowseRequestProfile(browseProfile, { slowMs: 1000 })
+
+    expect(wrappedFindOptions).to.not.equal(originalFindOptions)
+    expect(originalFindOptions).to.not.have.property('benchmark')
+    expect(callerLogging.calledOnceWithExactly('SELECT 1', 12)).to.equal(true)
+    expect(result.phases).to.deep.equal({ rows: 40 })
+  })
 })