From da490605b7312e85055948a0e68386fa8445b22e Mon Sep 17 00:00:00 2001 From: Jonathan Finley Date: Fri, 13 Mar 2026 21:07:13 -0400 Subject: [PATCH] fix: wire browse request timing hooks --- server/utils/profiler.js | 45 +++++++++--- .../queries/libraryBrowseInstrumentation.js | 42 +++++++++-- .../libraryBrowseInstrumentation.test.js | 72 +++++++++++++++++++ 3 files changed, 146 insertions(+), 13 deletions(-) diff --git a/server/utils/profiler.js b/server/utils/profiler.js index fa9581b6d..744b4ff8a 100644 --- a/server/utils/profiler.js +++ b/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`) diff --git a/server/utils/queries/libraryBrowseInstrumentation.js b/server/utils/queries/libraryBrowseInstrumentation.js index cb8374c07..00759b3d7 100644 --- a/server/utils/queries/libraryBrowseInstrumentation.js +++ b/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 } diff --git a/test/server/utils/libraryBrowseInstrumentation.test.js b/test/server/utils/libraryBrowseInstrumentation.test.js index 971ea2c1f..14892dd43 100644 --- a/test/server/utils/libraryBrowseInstrumentation.test.js +++ b/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 }) + }) })