Skip to content
Snippets Groups Projects
Unverified Commit a3cc159f authored by Rhys Arkins's avatar Rhys Arkins Committed by GitHub
Browse files

chore: extract and lookup duration logging (#20816)

parent 67b076ae
No related branches found
No related tags found
No related merge requests found
export interface LookupStats {
datasource: string;
duration: number;
}
...@@ -52,12 +52,20 @@ export async function extractAllDependencies( ...@@ -52,12 +52,20 @@ export async function extractAllDependencies(
extractResult.extractionFingerprints[manager] = hashMap.get(manager); extractResult.extractionFingerprints[manager] = hashMap.get(manager);
} }
const extractDurations: Record<string, number> = {};
const extractResults = await Promise.all( const extractResults = await Promise.all(
extractList.map(async (managerConfig) => { extractList.map(async (managerConfig) => {
const start = Date.now();
const packageFiles = await getManagerPackageFiles(managerConfig); const packageFiles = await getManagerPackageFiles(managerConfig);
const durationMs = Math.round(Date.now() - start);
extractDurations[managerConfig.manager] = durationMs;
return { manager: managerConfig.manager, packageFiles }; return { manager: managerConfig.manager, packageFiles };
}) })
); );
logger.debug(
{ managers: extractDurations },
'manager extract durations (ms)'
);
let fileCount = 0; let fileCount = 0;
for (const { manager, packageFiles } of extractResults) { for (const { manager, packageFiles } of extractResults) {
if (packageFiles?.length) { if (packageFiles?.length) {
......
...@@ -24,7 +24,7 @@ import { ensureOnboardingPr } from './onboarding/pr'; ...@@ -24,7 +24,7 @@ import { ensureOnboardingPr } from './onboarding/pr';
import { extractDependencies, updateRepo } from './process'; import { extractDependencies, updateRepo } from './process';
import type { ExtractResult } from './process/extract-update'; import type { ExtractResult } from './process/extract-update';
import { ProcessResult, processResult } from './result'; import { ProcessResult, processResult } from './result';
import { printRequestStats } from './stats'; import { printLookupStats, printRequestStats } from './stats';
// istanbul ignore next // istanbul ignore next
export async function renovateRepository( export async function renovateRepository(
...@@ -109,6 +109,7 @@ export async function renovateRepository( ...@@ -109,6 +109,7 @@ export async function renovateRepository(
const splits = getSplits(); const splits = getSplits();
logger.debug(splits, 'Repository timing splits (milliseconds)'); logger.debug(splits, 'Repository timing splits (milliseconds)');
printRequestStats(); printRequestStats();
printLookupStats();
printDnsStats(); printDnsStats();
clearDnsCache(); clearDnsCache();
schemaUtil.reportErrors(); schemaUtil.reportErrors();
......
...@@ -12,6 +12,8 @@ import type { ...@@ -12,6 +12,8 @@ import type {
PackageFile, PackageFile,
} from '../../../modules/manager/types'; } from '../../../modules/manager/types';
import { ExternalHostError } from '../../../types/errors/external-host-error'; 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 { clone } from '../../../util/clone';
import { applyPackageRules } from '../../../util/package-rules'; import { applyPackageRules } from '../../../util/package-rules';
import * as p from '../../../util/promises'; import * as p from '../../../util/promises';
...@@ -54,10 +56,15 @@ async function fetchDepUpdates( ...@@ -54,10 +56,15 @@ async function fetchDepUpdates(
} else { } else {
if (depConfig.datasource) { if (depConfig.datasource) {
try { try {
const start = Date.now();
dep = { dep = {
...dep, ...dep,
...(await lookupUpdates(depConfig as LookupUpdateConfig)), ...(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) { } catch (err) {
if ( if (
packageFileConfig.repoIsOnboarded || packageFileConfig.repoIsOnboarded ||
......
import { logger, mocked } from '../../../test/util'; import { logger, mocked } from '../../../test/util';
import type { Logger } from '../../logger/types'; import type { Logger } from '../../logger/types';
import * as _memCache from '../../util/cache/memory'; import * as _memCache from '../../util/cache/memory';
import type { LookupStats } from '../../util/cache/memory/types';
import type { RequestStats } from '../../util/http/types'; import type { RequestStats } from '../../util/http/types';
import { printRequestStats } from './stats'; import { printLookupStats, printRequestStats } from './stats';
jest.mock('../../util/cache/memory'); jest.mock('../../util/cache/memory');
...@@ -10,6 +11,44 @@ const memCache = mocked(_memCache); ...@@ -10,6 +11,44 @@ const memCache = mocked(_memCache);
const log = logger.logger as jest.Mocked<Logger>; const log = logger.logger as jest.Mocked<Logger>;
describe('workers/repository/stats', () => { 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()', () => { describe('printRequestStats()', () => {
it('runs', () => { it('runs', () => {
const getStats: number[] = [30, 100, 10, 20]; const getStats: number[] = [30, 100, 10, 20];
......
...@@ -2,6 +2,7 @@ import URL from 'url'; ...@@ -2,6 +2,7 @@ import URL from 'url';
import { logger } from '../../logger'; import { logger } from '../../logger';
import { sortNumeric } from '../../util/array'; import { sortNumeric } from '../../util/array';
import * as memCache from '../../util/cache/memory'; import * as memCache from '../../util/cache/memory';
import type { LookupStats } from '../../util/cache/memory/types';
import type { RequestStats } from '../../util/http/types'; import type { RequestStats } from '../../util/http/types';
interface CacheStats { interface CacheStats {
...@@ -11,6 +12,24 @@ interface CacheStats { ...@@ -11,6 +12,24 @@ interface CacheStats {
maxMs?: number; 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 { export function printRequestStats(): void {
const packageCacheGets = ( const packageCacheGets = (
memCache.get<number[]>('package-cache-gets') ?? [] memCache.get<number[]>('package-cache-gets') ?? []
......
0% Loading or .
You are about to add 0 people to the discussion. Proceed with caution.
Please register or to comment