diff --git a/app/main.ts b/app/main.ts index be6bd572bf52..a8b845c880ae 100644 --- a/app/main.ts +++ b/app/main.ts @@ -1784,6 +1784,8 @@ async function initializeSQL( sqlInitTimeEnd = Date.now(); } + sql.startTrackingQueryStats(); + // Only if we've initialized things successfully do we set up the corruption handler drop(runSQLCorruptionHandler()); drop(runSQLReadonlyHandler()); @@ -2107,6 +2109,8 @@ app.on('ready', async () => { innerLogger.info('Processed count:', processedCount); innerLogger.info('Messages per second:', messagesPerSec); + sql.stopTrackingQueryStats(); + event.sender.send('ci:event', 'app-loaded', { loadTime, sqlInitTime, diff --git a/ts/sql/main.ts b/ts/sql/main.ts index 9ec713c0679a..ee760f022fde 100644 --- a/ts/sql/main.ts +++ b/ts/sql/main.ts @@ -103,6 +103,13 @@ type PoolEntry = { load: number; }; +type QueryStatsType = { + queryName: string; + count: number; + cumulative: number; + max: number; +}; + export class MainSQL { private readonly pool = new Array(); @@ -126,6 +133,13 @@ export class MainSQL { private shouldTimeQueries = false; + private shouldTrackQueryStats = false; + + private queryStats?: { + start: number; + statsByQuery: Map; + }; + constructor() { const exitPromises = new Array>(); for (let i = 0; i < WORKER_COUNT; i += 1) { @@ -286,6 +300,22 @@ export class MainSQL { return result; } + public startTrackingQueryStats(): void { + if (this.shouldTrackQueryStats) { + this.logQueryStats(); + } + this.resetQueryStats(); + this.shouldTrackQueryStats = true; + } + + public stopTrackingQueryStats(): void { + if (this.shouldTrackQueryStats) { + this.logQueryStats(); + } + this.queryStats = undefined; + this.shouldTrackQueryStats = false; + } + private async send( entry: PoolEntry, request: WorkerRequest @@ -353,9 +383,56 @@ export class MainSQL { } } + private resetQueryStats() { + this.queryStats = { start: Date.now(), statsByQuery: new Map() }; + } + + private roundDuration(duration: number): number { + return Math.round(100 * duration) / 100; + } + + private logQueryStats(numberToLog: number = 10) { + if (!this.queryStats) { + return; + } + const duration = Date.now() - this.queryStats.start; + const sortedByCumulativeDuration = [ + ...this.queryStats.statsByQuery.values(), + ].sort((a, b) => (b.cumulative ?? 0) - (a.cumulative ?? 0)); + this.logger?.info( + `Top ${numberToLog} queries by cumulative duration (ms) over last ${duration}ms: ` + + `${sortedByCumulativeDuration + .slice(0, numberToLog) + .map(stats => { + return ( + `${stats.queryName}: cumulative ${this.roundDuration(stats.cumulative)} | ` + + `average: ${this.roundDuration(stats.cumulative / (stats.count || 1))} | ` + + `max: ${this.roundDuration(stats.max)} | ` + + `count: ${stats.count}` + ); + }) + .join(' ||| ')}` + ); + } + private traceDuration(method: string, duration: number): void { + if (this.shouldTrackQueryStats) { + if (!this.queryStats) { + this.resetQueryStats(); + } + strictAssert(this.queryStats, 'has been initialized'); + let currentStats = this.queryStats.statsByQuery.get(method); + if (!currentStats) { + currentStats = { count: 0, cumulative: 0, queryName: method, max: 0 }; + this.queryStats.statsByQuery.set(method, currentStats); + } + currentStats.count += 1; + currentStats.cumulative += duration; + currentStats.max = Math.max(currentStats.max, duration); + } + if (this.shouldTimeQueries && !app.isPackaged) { - const twoDecimals = Math.round(100 * duration) / 100; + const twoDecimals = this.roundDuration(duration); this.logger?.info(`MainSQL query: ${method}, duration=${twoDecimals}ms`); } if (duration > MIN_TRACE_DURATION) {