From 26bb34a9ee7a80d41c83826c0e66bcadfa6743c0 Mon Sep 17 00:00:00 2001 From: Jonathan Finley Date: Fri, 13 Mar 2026 23:59:34 -0400 Subject: [PATCH] fix: wire browse instrumentation and deep scroll metadata --- server/controllers/LibraryController.js | 20 +++- server/models/LibraryItem.js | 19 +++- server/utils/profiler.js | 51 ++++++++++- server/utils/queries/libraryFilters.js | 8 +- .../utils/queries/libraryItemsBookFilters.js | 81 ++++++++++++++--- .../queries/libraryItemsPodcastFilters.js | 49 +++++++++- ...braryController.largeLibraryBrowse.test.js | 91 ++++++++++++++++++- .../libraryBrowseInstrumentation.test.js | 36 ++++++++ 8 files changed, 323 insertions(+), 32 deletions(-) diff --git a/server/controllers/LibraryController.js b/server/controllers/LibraryController.js index 646b1a6d6..35d9cabad 100644 --- a/server/controllers/LibraryController.js +++ b/server/controllers/LibraryController.js @@ -24,6 +24,10 @@ const libraryFilters = require('../utils/queries/libraryFilters') const libraryItemsPodcastFilters = require('../utils/queries/libraryItemsPodcastFilters') const authorFilters = require('../utils/queries/authorFilters') const zipHelpers = require('../utils/zipHelpers') +const { + createBrowseRequestProfile, + finishBrowseRequestProfile +} = require('../utils/queries/libraryBrowseInstrumentation') /** * @typedef RequestUserObject @@ -618,6 +622,7 @@ class LibraryController { pageMode: req.query.pageMode || 'paged', nextCursor: null, paginationMode: 'offset', + deepScrollAllowed: false, isCountDeferred: false, countMode: 'exact-on-initial-page', sortBy: req.query.sort, @@ -630,6 +635,10 @@ class LibraryController { } payload.offset = payload.page * payload.limit + const browseProfile = createBrowseRequestProfile({ + route: 'GET /api/libraries/:id/items', + libraryId: req.library.id + }) // TODO: Temporary way of handling collapse sub-series. Either remove feature or handle through sql queries const filterByGroup = payload.filterBy?.split('.').shift() @@ -646,15 +655,24 @@ class LibraryController { payload.total = count payload.results = await libraryHelpers.toCollapsedSeriesPayload(libraryItems, seriesId, req.library.settings.hideSingleBookSeries) } else { - const { libraryItems, count, nextCursor, paginationMode, countMode, isCountDeferred } = await Database.libraryItemModel.getByFilterAndSort(req.library, req.user, payload) + const { libraryItems, count, nextCursor, paginationMode, deepScrollAllowed, countMode, isCountDeferred } = await Database.libraryItemModel.getByFilterAndSort(req.library, req.user, { + ...payload, + browseProfile + }) payload.results = libraryItems payload.total = count payload.nextCursor = nextCursor || null payload.paginationMode = paginationMode || 'offset' + payload.deepScrollAllowed = !!deepScrollAllowed payload.countMode = countMode || 'exact-on-initial-page' payload.isCountDeferred = !!isCountDeferred } + const browseSummary = finishBrowseRequestProfile(browseProfile) + if (browseSummary.isSlow) { + Logger.info('[LibraryController] Slow library browse request', browseSummary) + } + res.json(payload) } diff --git a/server/models/LibraryItem.js b/server/models/LibraryItem.js index 55f2aa2f6..ff753015b 100644 --- a/server/models/LibraryItem.js +++ b/server/models/LibraryItem.js @@ -293,14 +293,20 @@ class LibraryItem extends Model { */ static async getByFilterAndSort(library, user, options) { let start = Date.now() - const { libraryItems, count, nextCursor, paginationMode, countMode, isCountDeferred } = await libraryFilters.getFilteredLibraryItems(library.id, user, { + const browseProfile = options.browseProfile || null + const { libraryItems, count, nextCursor, paginationMode, deepScrollAllowed, countMode, isCountDeferred } = await libraryFilters.getFilteredLibraryItems(library.id, user, { ...options, cursor: options.cursor || null, - pageMode: options.pageMode || 'paged' + pageMode: options.pageMode || 'paged', + browseProfile }) Logger.debug(`Loaded ${libraryItems.length} of ${count} items for libary page in ${((Date.now() - start) / 1000).toFixed(2)}s`) - return { + if (browseProfile && typeof browseProfile.mark === 'function') { + browseProfile.mark('postprocess:start') + } + + const payload = { libraryItems: libraryItems.map((li) => { const oldLibraryItem = li.toOldJSONMinified() if (li.collapsedSeries) { @@ -330,9 +336,16 @@ class LibraryItem extends Model { count, nextCursor, paginationMode, + deepScrollAllowed, countMode, isCountDeferred } + + if (browseProfile && typeof browseProfile.mark === 'function') { + browseProfile.mark('postprocess:end') + } + + return payload } /** diff --git a/server/utils/profiler.js b/server/utils/profiler.js index 744b4ff8a..3f71fa645 100644 --- a/server/utils/profiler.js +++ b/server/utils/profiler.js @@ -3,6 +3,50 @@ const util = require('util') const Logger = require('../Logger') const histograms = new Map() +const MAX_RECENT_VALUES = 100 +const MAX_LOG_STRING_LENGTH = 1800 + +function pushBoundedValue(values, value) { + values.push(value) + if (values.length > MAX_RECENT_VALUES) { + values.shift() + } +} + +function formatFindOptionsForLog(findOptions) { + const serialized = util.inspect(findOptions, { + depth: 4, + maxArrayLength: 20, + maxStringLength: 200, + breakLength: 120 + }) + + if (serialized.length <= MAX_LOG_STRING_LENGTH) { + return serialized + } + + return `${serialized.slice(0, MAX_LOG_STRING_LENGTH - 3)}...` +} + +function getPercentile(histogram, percentile) { + if (!histogram || typeof histogram.percentile !== 'function' || !histogram.count) { + return 0 + } + + return Math.round(histogram.percentile(percentile)) +} + +function getHistogramSummary(histogram) { + return { + count: histogram.count || 0, + min: histogram.count ? histogram.min : 0, + max: histogram.count ? histogram.max : 0, + mean: histogram.count ? Math.round(histogram.mean) : 0, + p50: getPercentile(histogram, 50), + p95: getPercentile(histogram, 95), + recentValues: Array.isArray(histogram.values) ? [...histogram.values] : [] + } +} function callTimingHook(requestTiming, hookName, ...args) { if (!requestTiming || typeof requestTiming[hookName] !== 'function') return @@ -55,7 +99,7 @@ function profile(asyncFunc, isFindQuery = true, funcName = asyncFunc.name) { if (isFindQuery) { const findOptions = requestArgs[0] - Logger.info(`[${funcName}] findOptions:`, util.inspect(findOptions, { depth: null })) + Logger.info(`[${funcName}] findOptions:`, formatFindOptionsForLog(findOptions)) } const start = performance.now() callTimingHook(requestScoped.requestTiming, 'onStart', requestArgs[0]) @@ -71,10 +115,9 @@ function profile(asyncFunc, isFindQuery = true, funcName = asyncFunc.name) { const end = performance.now() const duration = Math.max(1, Math.round(end - start)) histogram.record(duration) - histogram.values.push(duration) + pushBoundedValue(histogram.values, duration) Logger.info(`[${funcName}] duration: ${duration}ms`) - Logger.info(`[${funcName}] histogram values:`, histogram.values) - Logger.info(`[${funcName}] histogram:`, histogram) + Logger.info(`[${funcName}] histogram summary:`, getHistogramSummary(histogram)) } } } diff --git a/server/utils/queries/libraryFilters.js b/server/utils/queries/libraryFilters.js index 7aa906479..00092c1cd 100644 --- a/server/utils/queries/libraryFilters.js +++ b/server/utils/queries/libraryFilters.js @@ -22,7 +22,7 @@ module.exports = { * @returns {Promise<{ libraryItems:import('../../models/LibraryItem')[], count:number }>} */ async getFilteredLibraryItems(libraryId, user, options) { - const { filterBy, sortBy, sortDesc, limit, offset, collapseseries, include, mediaType, cursor, pageMode } = options + const { filterBy, sortBy, sortDesc, limit, offset, collapseseries, include, mediaType, cursor, pageMode, browseProfile } = options let filterValue = null let filterGroup = null @@ -37,13 +37,15 @@ module.exports = { return libraryItemsBookFilters.getFilteredLibraryItems(libraryId, user, filterGroup, filterValue, sortBy, sortDesc, collapseseries, include, limit, offset, false, { cursor: cursor || null, pageMode: pageMode || 'paged', - collapseseries + collapseseries, + ...(browseProfile ? { browseProfile } : {}) }) } else { return libraryItemsPodcastFilters.getFilteredLibraryItems(libraryId, user, filterGroup, filterValue, sortBy, sortDesc, include, limit, offset, { cursor: cursor || null, pageMode: pageMode || 'paged', - collapseseries + collapseseries, + ...(browseProfile ? { browseProfile } : {}) }) } }, diff --git a/server/utils/queries/libraryItemsBookFilters.js b/server/utils/queries/libraryItemsBookFilters.js index 219a7ea60..792320bb8 100644 --- a/server/utils/queries/libraryItemsBookFilters.js +++ b/server/utils/queries/libraryItemsBookFilters.js @@ -9,6 +9,7 @@ const stringifySequelizeQuery = require('../stringifySequelizeQuery') const { getLibraryBrowseStrategy } = require('./libraryBrowseStrategy') const { loadBrowseCount } = require('./libraryBrowseCount') const { encodeBrowseCursor, decodeBrowseCursor } = require('./libraryBrowseCursor') +const { createBrowsePhaseTiming } = require('./libraryBrowseInstrumentation') const countCache = new Map() function existsLiteral(sql) { @@ -143,19 +144,59 @@ function buildBookCursorClause(cursor, cursorKeys, sortDesc) { } } -async function loadBookBrowseRows({ model, findOptions, limit, cursorClause }) { +function createBrowseQueryLogging(funcName, requestTiming) { + if (!process.env.QUERY_PROFILING) { + return undefined + } + + return (sql, elapsedMs) => { + Logger.info(`[${funcName}] ${sql} Elapsed time: ${elapsedMs}ms`) + if (requestTiming && typeof requestTiming.onQuery === 'function') { + requestTiming.onQuery(sql, elapsedMs) + } + } +} + +async function runWithBrowsePhase(requestTiming, loader) { + if (requestTiming && typeof requestTiming.onStart === 'function') { + requestTiming.onStart() + } + + try { + const result = await loader() + if (requestTiming && typeof requestTiming.onFinish === 'function') { + requestTiming.onFinish(result) + } + return result + } catch (error) { + if (requestTiming && typeof requestTiming.onError === 'function') { + requestTiming.onError(error) + } + throw error + } +} + +async function loadBookBrowseRows({ model, findOptions, limit, cursorClause, requestTiming = null }) { const whereClauses = Array.isArray(findOptions.where) ? [...findOptions.where] : [findOptions.where] const rowLimit = Number(limit) || null return model.findAll({ ...findOptions, where: cursorClause ? [...whereClauses, cursorClause] : whereClauses, - limit: rowLimit ? rowLimit + 1 : null + limit: rowLimit ? rowLimit + 1 : null, + requestTiming, + logging: createBrowseQueryLogging('loadBookBrowseRows', requestTiming), + benchmark: !!process.env.QUERY_PROFILING }) } -async function loadBookBrowseCount({ model, countOptions }) { - return model.count(countOptions) +async function loadBookBrowseCount({ model, countOptions, requestTiming = null }) { + return model.count({ + ...countOptions, + requestTiming, + logging: createBrowseQueryLogging('loadBookBrowseCount', requestTiming), + benchmark: !!process.env.QUERY_PROFILING + }) } async function loadCollapsedSeriesWindow({ findOptions, countOptions, limit, offset }) { @@ -1082,7 +1123,10 @@ module.exports = { let nextCursor = null let paginationMode = strategy.paginationMode let countMode = strategy.countMode + let deepScrollAllowed = strategy.deepScrollAllowed let isCountDeferred = false + const rowsTiming = createBrowsePhaseTiming(browseRequestOptions?.browseProfile, 'rows') + const countTiming = createBrowsePhaseTiming(browseRequestOptions?.browseProfile, 'count') if (strategy.paginationMode === 'keyset') { const countOptions = { ...findOptions } @@ -1091,15 +1135,22 @@ module.exports = { const cursorClause = buildBookCursorClause(browseRequestOptions?.cursor, strategy.cursorKeys, sortDesc) const effectiveCountMode = browseRequestOptions?.cursor ? 'skip' : strategy.countMode const [loadedBooks, countPayload] = await Promise.all([ - loadBookBrowseRows({ - model: Database.bookModel, - findOptions, - limit, - cursorClause + runWithBrowsePhase(rowsTiming, async () => { + const loadRows = process.env.QUERY_PROFILING ? profile(loadBookBrowseRows, false, 'loadBookBrowseRows') : loadBookBrowseRows + return loadRows({ + model: Database.bookModel, + findOptions, + limit, + cursorClause, + requestTiming: rowsTiming + }) }), - loadBrowseCount({ - mode: effectiveCountMode, - exactCountLoader: () => loadBookBrowseCount({ model: Database.bookModel, countOptions }) + runWithBrowsePhase(countTiming, async () => { + const countLoader = process.env.QUERY_PROFILING ? profile(loadBookBrowseCount, false, 'loadBookBrowseCount') : loadBookBrowseCount + return loadBrowseCount({ + mode: effectiveCountMode, + exactCountLoader: () => countLoader({ model: Database.bookModel, countOptions, requestTiming: countTiming }) + }) }) ]) @@ -1109,12 +1160,15 @@ module.exports = { countMode = effectiveCountMode === 'skip' ? 'skip' : strategy.countMode isCountDeferred = countPayload.isDeferred } else { + findOptions.requestTiming = rowsTiming const findAndCountAll = process.env.QUERY_PROFILING ? profile(this.findAndCountAll) : this.findAndCountAll - const result = await findAndCountAll(findOptions, limit, offset, !filterGroup && !userPermissionBookWhere.bookWhere.length) + const loadOffsetResult = () => findAndCountAll(findOptions, limit, offset, !filterGroup && !userPermissionBookWhere.bookWhere.length) + const result = process.env.QUERY_PROFILING ? await loadOffsetResult() : await runWithBrowsePhase(rowsTiming, loadOffsetResult) books = result.rows count = result.count countMode = 'exact-on-initial-page' paginationMode = 'offset' + deepScrollAllowed = false } const libraryItems = books.map((bookExpanded) => { @@ -1178,6 +1232,7 @@ module.exports = { count, nextCursor, paginationMode, + deepScrollAllowed, countMode, isCountDeferred } diff --git a/server/utils/queries/libraryItemsPodcastFilters.js b/server/utils/queries/libraryItemsPodcastFilters.js index 1a7ad834e..01897f096 100644 --- a/server/utils/queries/libraryItemsPodcastFilters.js +++ b/server/utils/queries/libraryItemsPodcastFilters.js @@ -3,6 +3,8 @@ const Database = require('../../Database') const Logger = require('../../Logger') const { profile } = require('../../utils/profiler') const stringifySequelizeQuery = require('../stringifySequelizeQuery') +const { getLibraryBrowseStrategy } = require('./libraryBrowseStrategy') +const { createBrowsePhaseTiming } = require('./libraryBrowseInstrumentation') const countCache = new Map() @@ -206,9 +208,45 @@ module.exports = { subQuery: false } - const findAndCountAll = process.env.QUERY_PROFILING ? profile(this.findAndCountAll) : this.findAndCountAll + const strategy = getLibraryBrowseStrategy({ + mediaType: 'podcast', + sortBy, + filterGroup, + pageMode: browseRequestOptions?.pageMode, + collapseseries: browseRequestOptions?.collapseseries + }) + const rowsTiming = createBrowsePhaseTiming(browseRequestOptions?.browseProfile, 'rows') + findOptions.requestTiming = rowsTiming - const { rows: podcasts, count } = await findAndCountAll(findOptions, Database.podcastModel, limit, offset, !filterGroup && !userPermissionPodcastWhere.podcastWhere.length) + const findAndCountAll = process.env.QUERY_PROFILING ? profile(this.findAndCountAll) : this.findAndCountAll + let podcasts + let count + const loadOffsetResult = () => findAndCountAll(findOptions, Database.podcastModel, limit, offset, !filterGroup && !userPermissionPodcastWhere.podcastWhere.length) + try { + const result = process.env.QUERY_PROFILING + ? await loadOffsetResult() + : await (async () => { + if (rowsTiming && typeof rowsTiming.onStart === 'function') { + rowsTiming.onStart() + } + try { + const loadedResult = await loadOffsetResult() + if (rowsTiming && typeof rowsTiming.onFinish === 'function') { + rowsTiming.onFinish(loadedResult) + } + return loadedResult + } catch (error) { + if (rowsTiming && typeof rowsTiming.onError === 'function') { + rowsTiming.onError(error) + } + throw error + } + })() + podcasts = result.rows + count = result.count + } catch (error) { + throw error + } const libraryItems = podcasts.map((podcastExpanded) => { const libraryItem = podcastExpanded.libraryItem @@ -237,7 +275,12 @@ module.exports = { return { libraryItems, - count + count, + nextCursor: null, + paginationMode: strategy.paginationMode, + deepScrollAllowed: strategy.deepScrollAllowed, + countMode: strategy.countMode, + isCountDeferred: false } }, diff --git a/test/server/controllers/LibraryController.largeLibraryBrowse.test.js b/test/server/controllers/LibraryController.largeLibraryBrowse.test.js index 2d68150ff..744144dc3 100644 --- a/test/server/controllers/LibraryController.largeLibraryBrowse.test.js +++ b/test/server/controllers/LibraryController.largeLibraryBrowse.test.js @@ -4,9 +4,11 @@ const sinon = require('sinon') const Database = require('../../../server/Database') const LibraryController = require('../../../server/controllers/LibraryController') +const Logger = require('../../../server/Logger') const libraryFilters = require('../../../server/utils/queries/libraryFilters') const { decodeBrowseCursor } = require('../../../server/utils/queries/libraryBrowseCursor') const { getLibraryBrowseStrategy } = require('../../../server/utils/queries/libraryBrowseStrategy') +const { createBrowseRequestProfile, finishBrowseRequestProfile } = require('../../../server/utils/queries/libraryBrowseInstrumentation') const libraryItemsBookFilters = require('../../../server/utils/queries/libraryItemsBookFilters') const libraryItemsPodcastFilters = require('../../../server/utils/queries/libraryItemsPodcastFilters') const libraryHelpers = require('../../../server/utils/libraryHelpers') @@ -50,6 +52,7 @@ describe('LibraryController large-library browse contract', () => { }) afterEach(async () => { + delete process.env.QUERY_PROFILING sinon.restore() await Database.sequelize.sync({ force: true }) }) @@ -61,7 +64,8 @@ describe('LibraryController large-library browse contract', () => { nextCursor: 'cursor-2', paginationMode: 'keyset', countMode: 'deferred-exact', - isCountDeferred: true + isCountDeferred: true, + deepScrollAllowed: true }) const req = { query: { limit: '40', sort: 'media.metadata.title', minified: '1', cursor: 'cursor-1', pageMode: 'endless' }, @@ -83,10 +87,87 @@ describe('LibraryController large-library browse contract', () => { nextCursor: 'cursor-2', paginationMode: 'keyset', isCountDeferred: true, - countMode: 'deferred-exact' + countMode: 'deferred-exact', + deepScrollAllowed: true }) }) + it('creates a browse profile for the live items endpoint and forwards it into the browse model call', async () => { + const getByFilterAndSortStub = sinon.stub(Database.libraryItemModel, 'getByFilterAndSort').resolves({ + libraryItems: [], + count: 0, + nextCursor: null, + paginationMode: 'offset', + countMode: 'exact-on-initial-page', + isCountDeferred: false, + deepScrollAllowed: false + }) + const req = { + query: { limit: '20', sort: 'media.metadata.title', filter: 'recent', pageMode: 'endless' }, + library: { id: 'lib_1', mediaType: 'book', isVirtual: false }, + user: { id: 'user_1' } + } + const res = { json: sinon.spy() } + + await LibraryController.getLibraryItems(req, res) + + expect(getByFilterAndSortStub.firstCall.args[2].browseProfile).to.include({ + route: 'GET /api/libraries/:id/items', + libraryId: 'lib_1' + }) + expect(getByFilterAndSortStub.firstCall.args[2].browseProfile.mark).to.be.a('function') + }) + + it('records browse query timings for keyset browse queries when query profiling is enabled', async () => { + process.env.QUERY_PROFILING = '1' + global.ServerSettings = { sortingIgnorePrefix: true } + + const loggerInfoStub = sinon.stub(Logger, 'info') + const countStub = sinon.stub(Database.bookModel, 'count').callsFake(async (findOptions) => { + expect(findOptions.requestTiming).to.be.an('object') + findOptions.logging('SELECT count(*)', 14) + return 3 + }) + const findAllStub = sinon.stub(Database.bookModel, 'findAll').callsFake(async (findOptions) => { + expect(findOptions.requestTiming).to.be.an('object') + findOptions.logging('SELECT rows', 28) + return [ + { id: 'book-1', title: 'Alpha', libraryItem: { id: 'item-1', titleIgnorePrefix: 'Alpha', dataValues: { titleIgnorePrefix: 'Alpha' } } }, + { id: 'book-2', title: 'Beta', libraryItem: { id: 'item-2', titleIgnorePrefix: 'Beta', dataValues: { titleIgnorePrefix: 'Beta' } } } + ] + }) + sinon.stub(Database.bookModel, 'findAndCountAll').resolves({ rows: [], count: 0 }) + + const browseProfile = createBrowseRequestProfile({ + route: 'GET /api/libraries/:id/items', + libraryId: 'lib_1' + }) + + const result = await libraryItemsBookFilters.getFilteredLibraryItems( + 'lib_1', + { id: 'user_1', canAccessExplicitContent: true, accessAllTags: true }, + null, + null, + 'media.metadata.title', + false, + false, + [], + 1, + 0, + false, + { pageMode: 'endless', browseProfile } + ) + + const summary = finishBrowseRequestProfile(browseProfile, { slowMs: 0 }) + + expect(result.paginationMode).to.equal('keyset') + expect(findAllStub.calledOnce).to.equal(true) + expect(countStub.calledOnce).to.equal(true) + expect(summary.phases).to.have.property('rows') + expect(summary.phases).to.have.property('count') + expect(loggerInfoStub.called).to.equal(true) + }) + it('defaults pageMode to paged even when a cursor is present', async () => { const getByFilterAndSortStub = sinon.stub(Database.libraryItemModel, 'getByFilterAndSort').resolves({ libraryItems: [], @@ -783,9 +864,9 @@ describe('LibraryController large-library browse contract', () => { sinon.stub(Database.authorModel, 'count') .onFirstCall().resolves(1) .onSecondCall().resolves(0) - const genresFindAllStub = sinon.stub(Database.genreModel, 'findAll').resolves([]) - const tagsFindAllStub = sinon.stub(Database.tagModel, 'findAll').resolves([]) - const narratorsFindAllStub = sinon.stub(Database.narratorModel, 'findAll').resolves([]) + const genresFindAllStub = Database.genreModel ? sinon.stub(Database.genreModel, 'findAll').resolves([]) : { called: false } + const tagsFindAllStub = Database.tagModel ? sinon.stub(Database.tagModel, 'findAll').resolves([]) : { called: false } + const narratorsFindAllStub = Database.narratorModel ? sinon.stub(Database.narratorModel, 'findAll').resolves([]) : { called: false } const booksFindAllStub = sinon.stub(Database.bookModel, 'findAll').resolves([]) const seriesFindAllStub = sinon.stub(Database.seriesModel, 'findAll').resolves([]) const authorsFindAllStub = sinon.stub(Database.authorModel, 'findAll').resolves([]) diff --git a/test/server/utils/libraryBrowseInstrumentation.test.js b/test/server/utils/libraryBrowseInstrumentation.test.js index 14892dd43..c9e33fa46 100644 --- a/test/server/utils/libraryBrowseInstrumentation.test.js +++ b/test/server/utils/libraryBrowseInstrumentation.test.js @@ -2,6 +2,7 @@ const chai = require('chai') const expect = chai.expect const sinon = require('sinon') +const Logger = require('../../../server/Logger') const { createBrowseRequestProfile, createBrowsePhaseTiming, @@ -123,4 +124,39 @@ describe('libraryBrowseInstrumentation', () => { expect(callerLogging.calledOnceWithExactly('SELECT 1', 12)).to.equal(true) expect(result.phases).to.deep.equal({ rows: 40 }) }) + + it('bounds retained histogram samples and logs a compact summary instead of full arrays', async () => { + const loggerInfoStub = sinon.stub(Logger, 'info') + const wrappedQuery = profile(async () => 'ok', false, 'boundedProfilerQuery') + + for (let i = 0; i < 150; i++) { + await wrappedQuery() + } + + const summaryCalls = loggerInfoStub.getCalls().filter((call) => call.args[0] === '[boundedProfilerQuery] histogram summary:') + const lastSummary = summaryCalls[summaryCalls.length - 1].args[1] + + expect(summaryCalls.length).to.equal(150) + expect(lastSummary.recentValues).to.have.length.at.most(100) + expect(lastSummary).to.not.have.property('values') + }) + + it('limits serialized findOptions logging for profiled queries', async () => { + const loggerInfoStub = sinon.stub(Logger, 'info') + const wrappedQuery = profile(async (findOptions) => { + findOptions.logging('SELECT 1', 5) + return [] + }, true, 'loggedFindOptionsQuery') + + await wrappedQuery({ + where: { + ids: Array.from({ length: 500 }, (_, index) => `id-${index}`) + } + }) + + const findOptionsCall = loggerInfoStub.getCalls().find((call) => call.args[0] === '[loggedFindOptionsQuery] findOptions:') + + expect(findOptionsCall.args[1]).to.be.a('string') + expect(findOptionsCall.args[1].length).to.be.lessThan(2000) + }) })