From a3cc159f7e30120da72b60196f3f8d706d5d5709 Mon Sep 17 00:00:00 2001 From: Rhys Arkins Date: Thu, 9 Mar 2023 12:24:50 +0100 Subject: [PATCH] chore: extract and lookup duration logging (#20816) --- lib/util/cache/memory/types.ts | 4 +++ lib/workers/repository/extract/index.ts | 8 +++++ lib/workers/repository/index.ts | 3 +- lib/workers/repository/process/fetch.ts | 7 +++++ lib/workers/repository/stats.spec.ts | 41 ++++++++++++++++++++++++- lib/workers/repository/stats.ts | 19 ++++++++++++ 6 files changed, 80 insertions(+), 2 deletions(-) create mode 100644 lib/util/cache/memory/types.ts diff --git a/lib/util/cache/memory/types.ts b/lib/util/cache/memory/types.ts new file mode 100644 index 00000000000000..c122e353b083f3 --- /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 57395bf4075eb9..a2337de4a45d26 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 = {}; 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 0d6f4dd0e7af91..5352b8123ed482 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 6d46cb4402ee98..c4ad809e510689 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('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 5c83dc53ecbd50..1b3d0cf4f408de 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; 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 dd95bb0b333993..049a4ce45a136f 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('lookup-stats') ?? []; + const datasourceDurations: Record = {}; + for (const lookup of lookups) { + datasourceDurations[lookup.datasource] ??= []; + datasourceDurations[lookup.datasource].push(lookup.duration); + } + const data: Record = {}; + 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('package-cache-gets') ?? []