feat(internal): log timing splits per-repository

lib/util/split.spec.ts

+import { addSplit, getSplits, splitInit } from './split';
+
+describe('util/split', () => {
+  it('adds splits and returns results', () => {
+    splitInit();
+    addSplit('one');
+    addSplit('two');
+    const res = getSplits();
+    expect(res.total).toBeDefined();
+    expect(Object.keys(res.splits)).toHaveLength(2);
+  });
+});

lib/util/split.ts

+let startTime = 0;
+let lastTime = 0;
+let splits: Record<string, number> = {};
+
+export function splitInit(): void {
+  splits = {};
+  startTime = Date.now();
+  lastTime = startTime;
+}
+
+export function addSplit(name: string): void {
+  splits[name] = Date.now() - lastTime;
+  lastTime = Date.now();
+}
+
+export function getSplits(): any {
+  return { splits, total: Date.now() - startTime };
+}

lib/workers/repository/index.ts

@@ -3,6 +3,7 @@ import fs from 'fs-extra';
 import { RenovateConfig } from '../../config';
 import { logger, setMeta } from '../../logger';
 import { platform } from '../../platform';
+import { addSplit, getSplits, splitInit } from '../../util/split';
 import handleError from './error';
 import { finaliseRepo } from './finalise';
 import { initRepo } from './init';
@@ -22,7 +23,7 @@ try {
 export async function renovateRepository(
   repoConfig: RenovateConfig
 ): Promise<ProcessResult> {
-  const startTime = Date.now();
+  splitInit();
   let config = { ...repoConfig };
   setMeta({ repository: config.repository });
   logger.info({ renovateVersion }, 'Repository started');
@@ -32,11 +33,13 @@ export async function renovateRepository(
     await fs.ensureDir(config.localDir);
     logger.debug('Using localDir: ' + config.localDir);
     config = await initRepo(config);
+    addSplit('init');
     const { branches, branchList, packageFiles } = await extractDependencies(
       config
     );
     await ensureOnboardingPr(config, packageFiles, branches);
     const res = await updateRepo(config, branches, branchList);
+    addSplit('update');
     if (res !== 'automerged') {
       await ensureMasterIssue(config, branches);
     }
@@ -51,6 +54,8 @@ export async function renovateRepository(
   if (config.localDir && !config.persistRepoData) {
     await fs.remove(config.localDir);
   }
-  logger.info({ durationMs: Date.now() - startTime }, 'Repository finished');
+  const splits = getSplits();
+  logger.debug(splits, 'Repository timing splits (milliseconds)');
+  logger.info({ durationMs: splits.total }, 'Repository finished');
   return repoResult;
 }

lib/workers/repository/process/extract-update.ts

 import { RenovateConfig } from '../../../config';
 import { logger } from '../../../logger';
 import { PackageFile } from '../../../manager/common';
+import { addSplit } from '../../../util/split';
 import { BranchConfig } from '../../common';
 import { extractAllDependencies } from '../extract';
 import { branchifyUpgrades } from '../updates/branchify';
@@ -45,16 +46,20 @@ function extractStats(packageFiles: Record<string, PackageFile[]>): any {
 
 export async function extract(config: RenovateConfig): Promise<ExtractResult> {
   logger.debug('extractAndUpdate()');
-  const startTime = Date.now();
   const packageFiles = await extractAllDependencies(config);
-  const durationMs = Math.round(Date.now() - startTime);
   const stats = extractStats(packageFiles);
   logger.info(
-    { baseBranch: config.baseBranch, stats, durationMs },
+    { baseBranch: config.baseBranch, stats },
     `Dependency extraction complete`
   );
+  addSplit(
+    config.baseBranches?.length ? `extract:${config.baseBranch}` : 'extract'
+  );
   logger.trace({ config: packageFiles }, 'packageFiles');
   await fetchUpdates(config, packageFiles);
+  addSplit(
+    config.baseBranches?.length ? `lookup:${config.baseBranch}` : 'lookup'
+  );
   logger.debug({ config: packageFiles }, 'packageFiles with updates');
   await raiseDeprecationWarnings(config, packageFiles);
   const { branches, branchList } = await branchifyUpgrades(
@@ -62,6 +67,9 @@ export async function extract(config: RenovateConfig): Promise<ExtractResult> {
     packageFiles
   );
   sortBranches(branches);
+  addSplit(
+    config.baseBranches?.length ? `branchify:${config.baseBranch}` : 'branchify'
+  );
   return { branches, branchList, packageFiles };
 }
 

lib/workers/repository/process/fetch.ts

@@ -114,11 +114,12 @@ export async function fetchUpdates(
   packageFiles: Record<string, PackageFile[]>
 ): Promise<void> {
   const managers = Object.keys(packageFiles);
-  const startTime = Date.now();
   const allManagerJobs = managers.map((manager) =>
     fetchManagerUpdates(config, packageFiles, manager)
   );
   await Promise.all(allManagerJobs);
-  const durationMs = Math.round(Date.now() - startTime);
-  logger.info({ durationMs }, 'Package releases lookups complete');
+  logger.debug(
+    { baseBranch: config.baseBranch },
+    'Package releases lookups complete'
+  );
 }