fix(git): report Git operation statistics at end of run

lib/instrumentation/index.spec.ts

@@ -1,6 +1,7 @@
 import { ProxyTracerProvider } from '@opentelemetry/api';
 import * as api from '@opentelemetry/api';
 import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node';
+import { GitOperationSpanProcessor } from '../util/git/span-processor';
 import {
   disableInstrumentations,
   getTracerProvider,
@@ -73,6 +74,7 @@ describe('instrumentation/index', () => {
               },
             },
           },
+          new GitOperationSpanProcessor(),
         ],
       },
     });
@@ -106,6 +108,7 @@ describe('instrumentation/index', () => {
               },
             },
           },
+          new GitOperationSpanProcessor(),
         ],
       },
     });

lib/instrumentation/index.ts

@@ -42,6 +42,7 @@ import {
 import { isPromise } from '@sindresorhus/is';
 import { pkg } from '../expose.cjs';
 import { getEnv } from '../util/env';
+import { GitOperationSpanProcessor } from '../util/git/span-processor';
 import type { RenovateSpanOptions } from './types';
 import {
   isTraceDebuggingEnabled,
@@ -69,6 +70,7 @@ export function init(): void {
   if (isTraceSendingEnabled()) {
     const exporter = new OTLPTraceExporter();
     spanProcessors.push(new BatchSpanProcessor(exporter));
+    spanProcessors.push(new GitOperationSpanProcessor());
   }
 
   const env = getEnv();

lib/util/git/span-processor.ts

@@ -0,0 +1,41 @@
+import type { Context } from '@opentelemetry/api';
+import type {
+  ReadableSpan,
+  Span,
+  SpanProcessor,
+} from '@opentelemetry/sdk-trace-base';
+import { ATTR_VCS_GIT_OPERATION_TYPE } from '../../instrumentation/types';
+import { GitOperationStats } from '../stats';
+import type { GitOperationType } from './types';
+
+export class GitOperationSpanProcessor implements SpanProcessor {
+  async forceFlush(): Promise<void> {
+    // no implementation
+  }
+  onStart(span: Span, parentContext: Context): void {
+    // no implementation
+  }
+  onEnd(span: ReadableSpan): void {
+    if (!span.ended) {
+      return;
+    }
+
+    if (!span.attributes[ATTR_VCS_GIT_OPERATION_TYPE]) {
+      return;
+    }
+
+    const start = span.startTime; // [seconds, nanos]
+    const end = span.endTime; // [seconds, nanos]
+    const startNs = start[0] * 1e9 + start[1];
+    const endNs = end[0] * 1e9 + end[1];
+    const ns = endNs - startNs;
+
+    GitOperationStats.write(
+      span.attributes[ATTR_VCS_GIT_OPERATION_TYPE] as GitOperationType,
+      ns / 1_000_000,
+    );
+  }
+  async shutdown(): Promise<void> {
+    // no implementation
+  }
+}

lib/util/stats.spec.ts

@@ -2,6 +2,7 @@ import * as memCache from './cache/memory';
 import {
   AbandonedPackageStats,
   DatasourceCacheStats,
+  GitOperationStats,
   HttpCacheStats,
   HttpStats,
   LookupStats,
@@ -666,4 +667,85 @@ describe('util/stats', () => {
       expect(logger.logger.debug).not.toHaveBeenCalled();
     });
   });
+
+  describe('GitOperationsStats', () => {
+    beforeEach(() => {
+      memCache.init();
+      vi.useFakeTimers();
+    });
+
+    afterEach(() => {
+      vi.useRealTimers();
+    });
+
+    it('returns empty report', () => {
+      const res = GitOperationStats.getReport();
+      expect(res).toEqual({});
+    });
+
+    it('writes data points', () => {
+      GitOperationStats.write('pull', 1000);
+      GitOperationStats.write('push', 100);
+      GitOperationStats.write('push', 50000);
+
+      const report = GitOperationStats.getReport();
+      expect(report).toEqual({
+        pull: {
+          avgMs: 1000,
+          count: 1,
+          maxMs: 1000,
+          medianMs: 1000,
+          totalMs: 1000,
+        },
+        push: {
+          avgMs: 25050,
+          count: 2,
+          maxMs: 50000,
+          medianMs: 50000,
+          totalMs: 50100,
+        },
+      });
+    });
+
+    it('rounds total towards ceiling when preparing report', () => {
+      GitOperationStats.write('pull', 1000.4);
+      GitOperationStats.write('pull', 500.4);
+      GitOperationStats.write('pull', 700.2);
+      GitOperationStats.write('pull', 5.500000001);
+
+      const report = GitOperationStats.getReport();
+      expect(report).toEqual({
+        pull: {
+          avgMs: 552,
+          count: 4,
+          // NOTE these are the raw values
+          maxMs: 1000.4,
+          medianMs: 700.2,
+          // NOTE that the total is rounded toward the ceiling
+          totalMs: 2207,
+        },
+      });
+    });
+
+    it('logs report', () => {
+      for (let i = 0; i < 5; i++) {
+        GitOperationStats.write('other', 4000);
+      }
+
+      GitOperationStats.report();
+
+      expect(logger.logger.debug).toHaveBeenCalledTimes(1);
+      const [data, msg] = logger.logger.debug.mock.calls[0];
+      expect(msg).toBe('Git operations statistics');
+      expect(data).toEqual({
+        other: {
+          avgMs: 4000,
+          count: 5,
+          maxMs: 4000,
+          medianMs: 4000,
+          totalMs: 20_000,
+        },
+      });
+    });
+  });
 });

lib/util/stats.ts

@@ -1,5 +1,6 @@
 import { logger } from '../logger';
 import * as memCache from './cache/memory';
+import type { GitOperationType } from './git/types';
 import { parseUrl } from './url';
 
 type LookupStatsData = Record<string, number[]>;
@@ -575,3 +576,31 @@ export class AbandonedPackageStats {
     }
   }
 }
+
+type GitOperationStatsData = Record<GitOperationType, number[]>;
+
+export class GitOperationStats {
+  static write(operationType: GitOperationType, duration: number): void {
+    const data =
+      memCache.get<GitOperationStatsData>('git-operations-stats') ?? {};
+    data[operationType] ??= [];
+    data[operationType].push(duration);
+    memCache.set('git-operations-stats', data);
+  }
+
+  static getReport(): Record<string, TimingStatsReport> {
+    const report: Record<string, TimingStatsReport> = {};
+    const data = memCache.get<LookupStatsData>('git-operations-stats') ?? {};
+    for (const [operationType, durations] of Object.entries(data)) {
+      report[operationType] = makeTimingReport(durations);
+      report[operationType].totalMs = Math.ceil(report[operationType].totalMs);
+    }
+
+    return report;
+  }
+
+  static report(): void {
+    const report = GitOperationStats.getReport();
+    logger.debug(report, 'Git operations statistics');
+  }
+}

lib/workers/repository/index.ts

@@ -23,6 +23,7 @@ import { addSplit, getSplits, splitInit } from '../../util/split';
 import {
   AbandonedPackageStats,
   DatasourceCacheStats,
+  GitOperationStats,
   HttpCacheStats,
   HttpStats,
   LookupStats,
@@ -207,6 +208,7 @@ export async function renovateRepository(
   LookupStats.report();
   ObsoleteCacheHitLogger.report();
   AbandonedPackageStats.report();
+  GitOperationStats.report();
   const cloned = isCloned();
   /* v8 ignore next 11 -- coverage not required of these `undefined` checks, as we're happy receiving an `undefined` in the logs */
   logger.info(