From 998705d5b0aea7f34d299fd085ff6791dbb8d34f Mon Sep 17 00:00:00 2001 From: Sergei Zharinov <zharinov@users.noreply.github.com> Date: Thu, 14 Mar 2024 12:06:53 -0300 Subject: [PATCH] refactor: Package cache stats utility (#27936) --- lib/util/array.ts | 4 -- lib/util/cache/package/index.ts | 36 +++++------ lib/util/stats.spec.ts | 96 +++++++++++++++++++++++++++- lib/util/stats.ts | 49 ++++++++++++++ lib/workers/repository/index.ts | 3 +- lib/workers/repository/stats.spec.ts | 22 +------ lib/workers/repository/stats.ts | 52 --------------- 7 files changed, 164 insertions(+), 98 deletions(-) diff --git a/lib/util/array.ts b/lib/util/array.ts index 41b2ad0679..485ef03fcf 100644 --- a/lib/util/array.ts +++ b/lib/util/array.ts @@ -7,10 +7,6 @@ export function coerceArray<T>(input: T[] | null | undefined): T[] { return []; } -export function sortNumeric(a: number, b: number): number { - return a - b; -} - // Useful for filtering an array so that it includes values that are not null or // undefined. This predicate acts as a type guard so that the resulting type for // `values.filter(isNotNullOrUndefined)` is `T[]`. diff --git a/lib/util/cache/package/index.ts b/lib/util/cache/package/index.ts index 6151dee52c..815d56d646 100644 --- a/lib/util/cache/package/index.ts +++ b/lib/util/cache/package/index.ts @@ -1,4 +1,5 @@ import type { AllConfig } from '../../../config/types'; +import { PackageCacheStats } from '../../stats'; import * as memCache from '../memory'; import * as fileCache from './file'; import * as redisCache from './redis'; @@ -18,20 +19,17 @@ export async function get<T = any>( if (!cacheProxy) { return undefined; } + const globalKey = getGlobalKey(namespace, key); - let start = 0; - if (memCache.get(globalKey) === undefined) { - memCache.set(globalKey, cacheProxy.get(namespace, key)); - start = Date.now(); - } - const result = await memCache.get(globalKey); - if (start) { - // Only count duration if it's not a duplicate - const durationMs = Math.round(Date.now() - start); - const cacheDurations = memCache.get<number[]>('package-cache-gets') ?? []; - cacheDurations.push(durationMs); - memCache.set('package-cache-gets', cacheDurations); + let p = memCache.get(globalKey); + if (!p) { + p = PackageCacheStats.wrapGet(() => + cacheProxy!.get<number[]>(namespace, key), + ); + memCache.set(globalKey, p); } + + const result = await p; return result; } @@ -44,14 +42,14 @@ export async function set( if (!cacheProxy) { return; } + + await PackageCacheStats.wrapSet(() => + cacheProxy!.set(namespace, key, value, minutes), + ); + const globalKey = getGlobalKey(namespace, key); - memCache.set(globalKey, value); - const start = Date.now(); - await cacheProxy.set(namespace, key, value, minutes); - const durationMs = Math.round(Date.now() - start); - const cacheDurations = memCache.get<number[]>('package-cache-sets') ?? []; - cacheDurations.push(durationMs); - memCache.set('package-cache-sets', cacheDurations); + const p = Promise.resolve(value); + memCache.set(globalKey, p); } export async function init(config: AllConfig): Promise<void> { diff --git a/lib/util/stats.spec.ts b/lib/util/stats.spec.ts index 84a6f54971..1d273e3c22 100644 --- a/lib/util/stats.spec.ts +++ b/lib/util/stats.spec.ts @@ -1,6 +1,6 @@ import { logger } from '../../test/util'; import * as memCache from './cache/memory'; -import { LookupStats, makeTimingReport } from './stats'; +import { LookupStats, PackageCacheStats, makeTimingReport } from './stats'; describe('util/stats', () => { beforeEach(() => { @@ -129,4 +129,98 @@ describe('util/stats', () => { }); }); }); + + describe('PackageCacheStats', () => { + beforeEach(() => { + jest.useFakeTimers(); + }); + + it('returns empty report', () => { + const res = PackageCacheStats.getReport(); + expect(res).toEqual({ + get: { avgMs: 0, count: 0, maxMs: 0, medianMs: 0, totalMs: 0 }, + set: { avgMs: 0, count: 0, maxMs: 0, medianMs: 0, totalMs: 0 }, + }); + }); + + it('writes data points', () => { + PackageCacheStats.writeGet(100); + PackageCacheStats.writeGet(200); + PackageCacheStats.writeGet(400); + PackageCacheStats.writeSet(1000); + + const res = PackageCacheStats.getReport(); + + expect(res).toEqual({ + get: { + avgMs: 233, + count: 3, + maxMs: 400, + medianMs: 200, + totalMs: 700, + }, + set: { + avgMs: 1000, + count: 1, + maxMs: 1000, + medianMs: 1000, + totalMs: 1000, + }, + }); + }); + + it('wraps get function', async () => { + const res = await PackageCacheStats.wrapGet(() => { + jest.advanceTimersByTime(100); + return Promise.resolve('foo'); + }); + + expect(res).toBe('foo'); + expect(PackageCacheStats.getReport()).toEqual({ + get: { avgMs: 100, count: 1, maxMs: 100, medianMs: 100, totalMs: 100 }, + set: { avgMs: 0, count: 0, maxMs: 0, medianMs: 0, totalMs: 0 }, + }); + }); + + it('wraps set function', async () => { + await PackageCacheStats.wrapSet(() => { + jest.advanceTimersByTime(100); + return Promise.resolve(); + }); + + expect(PackageCacheStats.getReport()).toEqual({ + get: { avgMs: 0, count: 0, maxMs: 0, medianMs: 0, totalMs: 0 }, + set: { avgMs: 100, count: 1, maxMs: 100, medianMs: 100, totalMs: 100 }, + }); + }); + + it('logs report', () => { + PackageCacheStats.writeGet(100); + PackageCacheStats.writeGet(200); + PackageCacheStats.writeGet(400); + PackageCacheStats.writeSet(1000); + + PackageCacheStats.report(); + + expect(logger.logger.debug).toHaveBeenCalledTimes(1); + const [data, msg] = logger.logger.debug.mock.calls[0]; + expect(msg).toBe('Package cache statistics'); + expect(data).toEqual({ + get: { + avgMs: 233, + count: 3, + maxMs: 400, + medianMs: 200, + totalMs: 700, + }, + set: { + avgMs: 1000, + count: 1, + maxMs: 1000, + medianMs: 1000, + totalMs: 1000, + }, + }); + }); + }); }); diff --git a/lib/util/stats.ts b/lib/util/stats.ts index 435c72374d..719431f315 100644 --- a/lib/util/stats.ts +++ b/lib/util/stats.ts @@ -54,3 +54,52 @@ export class LookupStats { logger.debug(report, 'Lookup statistics'); } } + +type PackageCacheData = number[]; + +export class PackageCacheStats { + static writeSet(duration: number): void { + const data = memCache.get<PackageCacheData>('package-cache-sets') ?? []; + data.push(duration); + memCache.set('package-cache-sets', data); + } + + static async wrapSet<T>(callback: () => Promise<T>): Promise<T> { + const start = Date.now(); + const result = await callback(); + const duration = Date.now() - start; + PackageCacheStats.writeSet(duration); + return result; + } + + static writeGet(duration: number): void { + const data = memCache.get<PackageCacheData>('package-cache-gets') ?? []; + data.push(duration); + memCache.set('package-cache-gets', data); + } + + static async wrapGet<T>(callback: () => Promise<T>): Promise<T> { + const start = Date.now(); + const result = await callback(); + const duration = Date.now() - start; + PackageCacheStats.writeGet(duration); + return result; + } + + static getReport(): { get: TimingStatsReport; set: TimingStatsReport } { + const packageCacheGets = + memCache.get<PackageCacheData>('package-cache-gets') ?? []; + const get = makeTimingReport(packageCacheGets); + + const packageCacheSets = + memCache.get<PackageCacheData>('package-cache-sets') ?? []; + const set = makeTimingReport(packageCacheSets); + + return { get, set }; + } + + static report(): void { + const report = PackageCacheStats.getReport(); + logger.debug(report, 'Package cache statistics'); + } +} diff --git a/lib/workers/repository/index.ts b/lib/workers/repository/index.ts index 94c86f8a3f..0939469178 100644 --- a/lib/workers/repository/index.ts +++ b/lib/workers/repository/index.ts @@ -19,7 +19,7 @@ import { clearDnsCache, printDnsStats } from '../../util/http/dns'; import * as queue from '../../util/http/queue'; import * as throttle from '../../util/http/throttle'; import { addSplit, getSplits, splitInit } from '../../util/split'; -import { LookupStats } from '../../util/stats'; +import { LookupStats, PackageCacheStats } from '../../util/stats'; import { setBranchCache } from './cache'; import { extractRepoProblems } from './common'; import { ensureDependencyDashboard } from './dependency-dashboard'; @@ -125,6 +125,7 @@ export async function renovateRepository( } const splits = getSplits(); logger.debug(splits, 'Repository timing splits (milliseconds)'); + PackageCacheStats.report(); printRequestStats(); LookupStats.report(); printDnsStats(); diff --git a/lib/workers/repository/stats.spec.ts b/lib/workers/repository/stats.spec.ts index 540ac8c13a..ac850dd638 100644 --- a/lib/workers/repository/stats.spec.ts +++ b/lib/workers/repository/stats.spec.ts @@ -12,8 +12,6 @@ describe('workers/repository/stats', () => { describe('printRequestStats()', () => { it('runs', () => { - memCache.set('package-cache-gets', [30, 100, 10, 20]); - memCache.set('package-cache-sets', [110, 80, 20]); memCache.set('http-requests', [ { method: 'get', @@ -60,7 +58,7 @@ describe('workers/repository/stats', () => { ]); expect(printRequestStats()).toBeUndefined(); expect(log.trace).toHaveBeenCalledOnce(); - expect(log.debug).toHaveBeenCalledTimes(2); + expect(log.debug).toHaveBeenCalledTimes(1); expect(log.trace.mock.calls[0][0]).toMatchInlineSnapshot(` { "allRequests": [ @@ -122,24 +120,6 @@ describe('workers/repository/stats', () => { } `); expect(log.debug.mock.calls[0][0]).toMatchInlineSnapshot(` - { - "get": { - "avgMs": 40, - "count": 4, - "maxMs": 100, - "medianMs": 20, - "totalMs": 160, - }, - "set": { - "avgMs": 70, - "count": 3, - "maxMs": 110, - "medianMs": 80, - "totalMs": 210, - }, - } - `); - expect(log.debug.mock.calls[1][0]).toMatchInlineSnapshot(` { "hostStats": { "api.github.com": { diff --git a/lib/workers/repository/stats.ts b/lib/workers/repository/stats.ts index a130e857c2..692dfd67a5 100644 --- a/lib/workers/repository/stats.ts +++ b/lib/workers/repository/stats.ts @@ -1,61 +1,9 @@ import URL from 'node:url'; import { logger } from '../../logger'; -import { sortNumeric } from '../../util/array'; import * as memCache from '../../util/cache/memory'; import type { RequestStats } from '../../util/http/types'; -interface CacheStats { - count: number; - avgMs?: number; - medianMs?: number; - maxMs?: number; - totalMs?: number; -} - export function printRequestStats(): void { - const packageCacheGets = ( - memCache.get<number[]>('package-cache-gets') ?? [] - ).sort(sortNumeric); - const packageCacheSets = ( - memCache.get<number[]>('package-cache-sets') ?? [] - ).sort(sortNumeric); - const packageCacheStats: Record<string, CacheStats> = { - get: { - count: packageCacheGets.length, - }, - set: { - count: packageCacheSets.length, - }, - }; - if (packageCacheGets.length) { - packageCacheStats.get.totalMs = Math.round( - packageCacheGets.reduce((a, b) => a + b, 0), - ); - packageCacheStats.get.avgMs = Math.round( - packageCacheStats.get.totalMs / packageCacheGets.length, - ); - if (packageCacheGets.length > 1) { - packageCacheStats.get.medianMs = - packageCacheGets[Math.round(packageCacheGets.length / 2) - 1]; - packageCacheStats.get.maxMs = - packageCacheGets[packageCacheGets.length - 1]; - } - } - if (packageCacheSets.length) { - packageCacheStats.set.totalMs = Math.round( - packageCacheSets.reduce((a, b) => a + b, 0), - ); - packageCacheStats.set.avgMs = Math.round( - packageCacheStats.set.totalMs / packageCacheSets.length, - ); - if (packageCacheSets.length > 1) { - packageCacheStats.set.medianMs = - packageCacheSets[Math.round(packageCacheSets.length / 2) - 1]; - packageCacheStats.set.maxMs = - packageCacheSets[packageCacheSets.length - 1]; - } - } - logger.debug(packageCacheStats, 'Package cache statistics'); const httpRequests = memCache.get<RequestStats[]>('http-requests'); // istanbul ignore next if (!httpRequests) { -- GitLab