diff --git a/lib/instrumentation/index.spec.ts b/lib/instrumentation/index.spec.ts index b3a68eea589..07ec65ee586 100644 --- a/lib/instrumentation/index.spec.ts +++ b/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(), ], }, }); diff --git a/lib/instrumentation/index.ts b/lib/instrumentation/index.ts index 17a7720dcec..370051c79ae 100644 --- a/lib/instrumentation/index.ts +++ b/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(); diff --git a/lib/util/git/span-processor.ts b/lib/util/git/span-processor.ts new file mode 100644 index 00000000000..0ac557a6179 --- /dev/null +++ b/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 { + // 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 { + // no implementation + } +} diff --git a/lib/util/stats.spec.ts b/lib/util/stats.spec.ts index 19ddb0830a4..1a2732c1884 100644 --- a/lib/util/stats.spec.ts +++ b/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, + }, + }); + }); + }); }); diff --git a/lib/util/stats.ts b/lib/util/stats.ts index 50e724ced61..d78798ea020 100644 --- a/lib/util/stats.ts +++ b/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; @@ -575,3 +576,31 @@ export class AbandonedPackageStats { } } } + +type GitOperationStatsData = Record; + +export class GitOperationStats { + static write(operationType: GitOperationType, duration: number): void { + const data = + memCache.get('git-operations-stats') ?? {}; + data[operationType] ??= []; + data[operationType].push(duration); + memCache.set('git-operations-stats', data); + } + + static getReport(): Record { + const report: Record = {}; + const data = memCache.get('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'); + } +} diff --git a/lib/workers/repository/index.ts b/lib/workers/repository/index.ts index a15bd6df8a8..73024b5a7fe 100644 --- a/lib/workers/repository/index.ts +++ b/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(