chore: extract and lookup duration logging (#20816)

lib/util/cache/memory/types.ts

@@ -0,0 +1,4 @@
+export interface LookupStats {
+  datasource: string;
+  duration: number;
+}

lib/workers/repository/extract/index.ts

@@ -52,12 +52,20 @@ export async function extractAllDependencies(
     extractResult.extractionFingerprints[manager] = hashMap.get(manager);
   }
 
+  const extractDurations: Record<string, number> = {};
   const extractResults = await Promise.all(
     extractList.map(async (managerConfig) => {
+      const start = Date.now();
       const packageFiles = await getManagerPackageFiles(managerConfig);
+      const durationMs = Math.round(Date.now() - start);
+      extractDurations[managerConfig.manager] = durationMs;
       return { manager: managerConfig.manager, packageFiles };
     })
   );
+  logger.debug(
+    { managers: extractDurations },
+    'manager extract durations (ms)'
+  );
   let fileCount = 0;
   for (const { manager, packageFiles } of extractResults) {
     if (packageFiles?.length) {

lib/workers/repository/index.ts

@@ -24,7 +24,7 @@ import { ensureOnboardingPr } from './onboarding/pr';
 import { extractDependencies, updateRepo } from './process';
 import type { ExtractResult } from './process/extract-update';
 import { ProcessResult, processResult } from './result';
-import { printRequestStats } from './stats';
+import { printLookupStats, printRequestStats } from './stats';
 
 // istanbul ignore next
 export async function renovateRepository(
@@ -109,6 +109,7 @@ export async function renovateRepository(
   const splits = getSplits();
   logger.debug(splits, 'Repository timing splits (milliseconds)');
   printRequestStats();
+  printLookupStats();
   printDnsStats();
   clearDnsCache();
   schemaUtil.reportErrors();

lib/workers/repository/process/fetch.ts

@@ -12,6 +12,8 @@ import type {
   PackageFile,
 } from '../../../modules/manager/types';
 import { ExternalHostError } from '../../../types/errors/external-host-error';
+import * as memCache from '../../../util/cache/memory';
+import type { LookupStats } from '../../../util/cache/memory/types';
 import { clone } from '../../../util/clone';
 import { applyPackageRules } from '../../../util/package-rules';
 import * as p from '../../../util/promises';
@@ -54,10 +56,15 @@ async function fetchDepUpdates(
   } else {
     if (depConfig.datasource) {
       try {
+        const start = Date.now();
         dep = {
           ...dep,
           ...(await lookupUpdates(depConfig as LookupUpdateConfig)),
         };
+        const duration = Date.now() - start;
+        const lookups = memCache.get<LookupStats[]>('lookup-stats') || [];
+        lookups.push({ datasource: depConfig.datasource, duration });
+        memCache.set('lookup-stats', lookups);
       } catch (err) {
         if (
           packageFileConfig.repoIsOnboarded ||

lib/workers/repository/stats.spec.ts

@@ -1,15 +1,54 @@
 import { logger, mocked } from '../../../test/util';
 import type { Logger } from '../../logger/types';
 import * as _memCache from '../../util/cache/memory';
+import type { LookupStats } from '../../util/cache/memory/types';
 import type { RequestStats } from '../../util/http/types';
-import { printRequestStats } from './stats';
+import { printLookupStats, printRequestStats } from './stats';
 
 jest.mock('../../util/cache/memory');
 
 const memCache = mocked(_memCache);
 const log = logger.logger as jest.Mocked<Logger>;
 
 describe('workers/repository/stats', () => {
+  describe('printLookupStats()', () => {
+    it('runs', () => {
+      const stats: LookupStats[] = [
+        {
+          datasource: 'npm',
+          duration: 100,
+        },
+        {
+          datasource: 'npm',
+          duration: 200,
+        },
+        {
+          datasource: 'docker',
+          duration: 1000,
+        },
+      ];
+      memCache.get.mockImplementationOnce(() => stats as any);
+      expect(printLookupStats()).toBeUndefined();
+      expect(log.debug).toHaveBeenCalledTimes(1);
+      expect(log.debug.mock.calls[0][0]).toMatchInlineSnapshot(`
+        {
+          "docker": {
+            "averageMs": 1000,
+            "count": 1,
+            "maximumMs": 1000,
+            "totalMs": 1000,
+          },
+          "npm": {
+            "averageMs": 150,
+            "count": 2,
+            "maximumMs": 200,
+            "totalMs": 300,
+          },
+        }
+      `);
+    });
+  });
+
   describe('printRequestStats()', () => {
     it('runs', () => {
       const getStats: number[] = [30, 100, 10, 20];

lib/workers/repository/stats.ts

@@ -2,6 +2,7 @@ import URL from 'url';
 import { logger } from '../../logger';
 import { sortNumeric } from '../../util/array';
 import * as memCache from '../../util/cache/memory';
+import type { LookupStats } from '../../util/cache/memory/types';
 import type { RequestStats } from '../../util/http/types';
 
 interface CacheStats {
@@ -11,6 +12,24 @@ interface CacheStats {
   maxMs?: number;
 }
 
+export function printLookupStats(): void {
+  const lookups = memCache.get<LookupStats[]>('lookup-stats') ?? [];
+  const datasourceDurations: Record<string, number[]> = {};
+  for (const lookup of lookups) {
+    datasourceDurations[lookup.datasource] ??= [];
+    datasourceDurations[lookup.datasource].push(lookup.duration);
+  }
+  const data: Record<string, unknown> = {};
+  for (const [datasource, durations] of Object.entries(datasourceDurations)) {
+    const count = durations.length;
+    const totalMs = durations.reduce((a, c) => a + c, 0);
+    const averageMs = Math.round(totalMs / count);
+    const maximumMs = Math.max(...durations);
+    data[datasource] = { count, averageMs, totalMs, maximumMs };
+  }
+  logger.debug(data, 'Package lookup durations');
+}
+
 export function printRequestStats(): void {
   const packageCacheGets = (
     memCache.get<number[]>('package-cache-gets') ?? []