diff --git a/lib/util/cache/memory/types.ts b/lib/util/cache/memory/types.ts new file mode 100644 index 0000000000000000000000000000000000000000..c122e353b083f31b88f5ce393323cddd93baf492 --- /dev/null +++ b/lib/util/cache/memory/types.ts @@ -0,0 +1,4 @@ +export interface LookupStats { + datasource: string; + duration: number; +} diff --git a/lib/workers/repository/extract/index.ts b/lib/workers/repository/extract/index.ts index 57395bf4075eb9ff91b927829d680314bdb0e2c1..a2337de4a45d263ad7287bbf9f1d9535b85aff47 100644 --- a/lib/workers/repository/extract/index.ts +++ b/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) { diff --git a/lib/workers/repository/index.ts b/lib/workers/repository/index.ts index 0d6f4dd0e7af917facc97d4ffdc46f0a3d6777f2..5352b8123ed4824a97462f9bc7b3d4639204ee86 100644 --- a/lib/workers/repository/index.ts +++ b/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(); diff --git a/lib/workers/repository/process/fetch.ts b/lib/workers/repository/process/fetch.ts index 6d46cb4402ee98039e4342e3290d5df27b6ba10d..c4ad809e5106897d7dbc6c90f71396214dfab6df 100644 --- a/lib/workers/repository/process/fetch.ts +++ b/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 || diff --git a/lib/workers/repository/stats.spec.ts b/lib/workers/repository/stats.spec.ts index 5c83dc53ecbd502250a81a2994dd01415bca372a..1b3d0cf4f408de2b8d887c5b44834fada3d72406 100644 --- a/lib/workers/repository/stats.spec.ts +++ b/lib/workers/repository/stats.spec.ts @@ -1,8 +1,9 @@ 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'); @@ -10,6 +11,44 @@ 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]; diff --git a/lib/workers/repository/stats.ts b/lib/workers/repository/stats.ts index dd95bb0b333993a92f8d7b593991a4998192dcdd..049a4ce45a136f868b30bb8b7042446429f5b6f3 100644 --- a/lib/workers/repository/stats.ts +++ b/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') ?? []