refactor: Package cache stats utility (#27936)

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[]`.

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> {

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,
+        },
+      });
+    });
+  });
 });

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');
+  }
+}

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();

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": {

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) {