feat: log host stats per run

Closes #6357

lib/util/http/index.ts

@@ -102,11 +102,19 @@ export class Http<GetOptions = HttpOptions, PostOptions = HttpPostOptions> {
         return cloneResponse<T>(await cachedRes);
       }
     }
+    const startTime = Date.now();
     const promisedRes = got(url, options);
     if (options.method === 'get') {
       runCache.set(cacheKey, promisedRes); // always set if it's a get
     }
     const res = await promisedRes;
+    const httpRequests = runCache.get('http-requests') || [];
+    httpRequests.push({
+      method: options.method,
+      url,
+      duration: Date.now() - startTime,
+    });
+    runCache.set('http-requests', httpRequests);
     return cloneResponse<T>(res);
   }
 

lib/workers/repository/index.ts

@@ -10,6 +10,7 @@ import { ensureMasterIssue } from './master-issue';
 import { ensureOnboardingPr } from './onboarding/pr';
 import { extractDependencies, updateRepo } from './process';
 import { ProcessResult, processResult } from './result';
+import { printRequestStats } from './stats';
 
 let renovateVersion = 'unknown';
 try {
@@ -55,6 +56,7 @@ export async function renovateRepository(
   }
   const splits = getSplits();
   logger.debug(splits, 'Repository timing splits (milliseconds)');
+  printRequestStats();
   logger.info({ durationMs: splits.total }, 'Repository finished');
   return repoResult;
 }

lib/workers/repository/stats.spec.ts

+import * as runCache_ from '../../util/cache/run';
+import { printRequestStats } from './stats';
+
+jest.mock('../../util/cache/run');
+
+const runCache: any = runCache_ as any;
+
+describe('workers/repository/stats', () => {
+  describe('printRequestStats()', () => {
+    it('runs', () => {
+      runCache.get = jest.fn(() => [
+        {
+          method: 'get',
+          url: 'https://api.github.com/api/v3/user',
+          duration: 100,
+        },
+        {
+          method: 'post',
+          url: 'https://api.github.com/graphql',
+          duration: 130,
+        },
+        {
+          method: 'post',
+          url: 'https://api.github.com/graphql',
+          duration: 150,
+        },
+        {
+          method: 'get',
+          url: 'https://api.github.com/api/v3/repositories',
+          duration: 500,
+        },
+        { method: 'get', url: 'https://auth.docker.io', duration: 200 },
+      ]);
+      expect(printRequestStats()).toBeUndefined();
+    });
+  });
+});

lib/workers/repository/stats.ts

+import URL from 'url';
+import { logger } from '../../logger';
+import * as runCache from '../../util/cache/run';
+
+export function printRequestStats(): void {
+  const httpRequests = runCache.get('http-requests');
+  if (!httpRequests) {
+    return;
+  }
+  httpRequests.sort((a, b) => {
+    if (a.url === b.url) {
+      return 0;
+    }
+    if (a.url < b.url) {
+      return -1;
+    }
+    return 1;
+  });
+  const allRequests: string[] = [];
+  const requestHosts: Record<string, number[]> = {};
+  for (const request of httpRequests) {
+    allRequests.push(
+      `${request.method.toUpperCase()} ${request.url} ${request.duration}`
+    );
+    const { hostname } = URL.parse(request.url);
+    requestHosts[hostname] = requestHosts[hostname] || [];
+    requestHosts[hostname].push(request.duration);
+  }
+  logger.trace({ allRequests, requestHosts }, 'full stats');
+  const hostStats: string[] = [];
+  let totalRequests = 0;
+  for (const [hostname, requests] of Object.entries(requestHosts)) {
+    const hostRequests = requests.length;
+    totalRequests += hostRequests;
+    const requestSum = requests.reduce((a, b) => a + b, 0);
+    const avg = Math.round(requestSum / hostRequests);
+    const requestCount =
+      `${hostRequests} ` + (hostRequests > 1 ? 'requests' : 'request');
+    hostStats.push(`${hostname}, ${requestCount}, ${avg}ms average`);
+  }
+  logger.debug({ hostStats, totalRequests }, 'http statistics');
+}