fix(spanner): record fractional latency metrics

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,

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();