diff --git a/handwritten/spanner/src/metrics/metrics-tracer.ts b/handwritten/spanner/src/metrics/metrics-tracer.ts index d41347a03c7e..709df2987939 100644 --- a/handwritten/spanner/src/metrics/metrics-tracer.ts +++ b/handwritten/spanner/src/metrics/metrics-tracer.ts @@ -31,11 +31,11 @@ import {Spanner} from '..'; * by MetricsTracer to monitor and report metrics for each individual gRPC call attempt. */ class MetricAttemptTracer { - private _startTime: Date; + private _startTime: number; public status: string; constructor() { - this._startTime = new Date(Date.now()); + this._startTime = performance.now(); this.status = Status[Status.UNKNOWN]; } @@ -67,12 +67,12 @@ class MetricAttemptTracer { */ class MetricOperationTracer { private _attemptCount: number; - private _startTime: Date; + private _startTime: number; private _currentAttempt: MetricAttemptTracer | null; constructor() { this._attemptCount = 0; - this._startTime = new Date(Date.now()); + this._startTime = performance.now(); this._currentAttempt = null; } @@ -173,13 +173,13 @@ export class MetricsTracer { } /** - * Returns the difference in milliseconds between two Date objects. + * Returns the difference in milliseconds between two times. * @param start The start time. * @param end The end time. * @returns The time difference in milliseconds. */ - private _getMillisecondTimeDifference(start: Date, end: Date): number { - return end.valueOf() - start.valueOf(); + private _getMillisecondTimeDifference(start: number, end: number): number { + return end - start; } /** @@ -235,7 +235,7 @@ export class MetricsTracer { if (!this.enabled) return; this.currentOperation!.currentAttempt!.status = Status[statusCode]; const attemptAttributes = this._createAttemptOtelAttributes(); - const endTime = new Date(Date.now()); + const endTime = performance.now(); const attemptLatencyMilliseconds = this._getMillisecondTimeDifference( this.currentOperation!.currentAttempt!.startTime, endTime, @@ -265,7 +265,7 @@ export class MetricsTracer { */ public recordOperationCompletion() { if (!this.enabled || !this.currentOperation) return; - const endTime = new Date(Date.now()); + const endTime = performance.now(); const operationAttributes = this._createOperationOtelAttributes(); const operationLatencyMilliseconds = this._getMillisecondTimeDifference( this.currentOperation!.startTime, diff --git a/handwritten/spanner/test/metrics/metrics-tracer.ts b/handwritten/spanner/test/metrics/metrics-tracer.ts index fef4e9099445..3cd5530f5bca 100644 --- a/handwritten/spanner/test/metrics/metrics-tracer.ts +++ b/handwritten/spanner/test/metrics/metrics-tracer.ts @@ -113,6 +113,21 @@ describe('MetricsTracer', () => { ); }); + it('should record fractional latency with sub-millisecond precision', () => { + const nowStub = sandbox.stub(performance, 'now'); + nowStub.onCall(0).returns(100.0); // op start + nowStub.onCall(1).returns(200.5); // attempt start + nowStub.onCall(2).returns(202.75); // attempt end + + tracer.recordOperationStart(); + tracer.recordAttemptStart(); + tracer.recordAttemptCompletion(Status.OK); + + assert.strictEqual(fakeAttemptLatency.record.calledOnce, true); + const [[latency]] = fakeAttemptLatency.record.args; + assert.strictEqual(latency, 2.25); // 202.75 - 200.5 + }); + it('should do nothing if disabled', () => { tracer.enabled = false; tracer.recordAttemptStart(); @@ -142,6 +157,27 @@ describe('MetricsTracer', () => { assert.strictEqual(opAttrs[Constants.METRIC_LABEL_KEY_STATUS], 'OK'); }); + it('should record fractional operation latency with sub-millisecond precision', () => { + const nowStub = sandbox.stub(performance, 'now'); + nowStub.onCall(0).returns(100.5); // op start + nowStub.onCall(1).returns(105.0); // attempt start + nowStub.onCall(2).returns(108.0); // attempt end + nowStub.onCall(3).returns(110.25); // op end + + sandbox.stub(MetricsTracerFactory, 'getInstance').returns({ + clearCurrentTracer: sinon.spy(), + } as any); + + tracer.recordOperationStart(); + tracer.recordAttemptStart(); + tracer.recordAttemptCompletion(Status.OK); + tracer.recordOperationCompletion(); + + assert.strictEqual(fakeOperationLatency.record.calledOnce, true); + const [[latency]] = fakeOperationLatency.record.args; + assert.strictEqual(latency, 9.75); // 110.25 - 100.5 + }); + it('should do nothing if disabled', () => { tracer.enabled = false; tracer.recordOperationCompletion();