fix: replace hrtime with performance not to allocate (#1204)

Signed-off-by: ferhat elmas <elmas.ferhat@gmail.com>

Author: ferhatelmas

src/http/plugins/metrics.test.ts

@@ -3,6 +3,34 @@ import Fastify from 'fastify'
 import { httpMetrics } from './metrics'
 
 describe('httpMetrics plugin', () => {
+  it('uses numeric monotonic timestamps for request duration metrics', async () => {
+    const app = Fastify()
+    const httpMetricsSpy = vi.spyOn(monitoringMetrics, 'recordHttpRequestMetrics')
+    const performanceNowSpy = vi.spyOn(performance, 'now').mockReturnValue(0)
+    let metricsStartTime: unknown
+
+    await app.register(httpMetrics())
+    app.get('/objects/:bucket', async (request) => {
+      metricsStartTime = request.metricsStartTime
+      return 'ok'
+    })
+
+    try {
+      const response = await app.inject({
+        method: 'GET',
+        url: '/objects/bucket-a',
+      })
+
+      expect(response.statusCode).toBe(200)
+      expect(metricsStartTime).toBe(0)
+      expect(httpMetricsSpy).toHaveBeenCalledWith(0, undefined, 2, 'GET', 'unknown', 200)
+    } finally {
+      performanceNowSpy.mockRestore()
+      httpMetricsSpy.mockRestore()
+      await app.close()
+    }
+  })
+
   it('records HTTP metric attributes without tenant id labels', async () => {
     const app = Fastify()
     const httpMetricsSpy = vi.spyOn(monitoringMetrics, 'recordHttpRequestMetrics')

src/http/plugins/metrics.ts

@@ -68,7 +68,7 @@ export const httpMetrics = (options: HttpMetricsOptions = {}) =>
       // Hook into request lifecycle to measure duration
       fastify.addHook('onRequest', (request, _reply, done) => {
         // Store start time on request for later use
-        request.metricsStartTime = process.hrtime.bigint()
+        request.metricsStartTime = performance.now()
         done()
       })
 
@@ -82,15 +82,13 @@ export const httpMetrics = (options: HttpMetricsOptions = {}) =>
         }
 
         const startTime = request.metricsStartTime
-        if (!startTime) {
+        if (startTime === undefined) {
           done()
           return
         }
 
         // Calculate duration in seconds
-        const endTime = process.hrtime.bigint()
-        const durationNs = endTime - startTime
-        const durationSeconds = Number(durationNs) / 1e9
+        const durationSeconds = (performance.now() - startTime) / 1000
 
         const operation =
           request.operation?.type || request.routeOptions?.config?.operation?.type || 'unknown'
@@ -120,6 +118,6 @@ export const httpMetrics = (options: HttpMetricsOptions = {}) =>
 // Extend FastifyRequest to include metricsStartTime
 declare module 'fastify' {
   interface FastifyRequest {
-    metricsStartTime?: bigint
+    metricsStartTime?: number
   }
 }

src/internal/queue/event.test.ts

@@ -1,3 +1,4 @@
+import { queueJobSchedulingTime } from '@internal/monitoring/metrics'
 import { vi } from 'vitest'
 
 type EventModule = typeof import('./event')
@@ -174,4 +175,33 @@ describe('Event payload versioning', () => {
       })
     )
   })
+
+  it('records queue scheduling duration from numeric monotonic timestamps', async () => {
+    const { eventModule, queueModule } = await loadQueueModules({
+      pgQueueEnable: true,
+    })
+    const TestEvent = defineTestEvent(eventModule.Event)
+    const payload = createPayload()
+    const send = vi.fn().mockResolvedValue('job-id')
+    const recordSpy = vi.spyOn(queueJobSchedulingTime, 'record')
+    const performanceNowSpy = vi
+      .spyOn(performance, 'now')
+      .mockReturnValueOnce(20)
+      .mockReturnValueOnce(26)
+
+    vi.spyOn(queueModule.Queue, 'getInstance').mockReturnValue({
+      send,
+    } as unknown as ReturnType<typeof queueModule.Queue.getInstance>)
+
+    try {
+      await TestEvent.send(payload)
+
+      expect(recordSpy).toHaveBeenCalledWith(0.006, {
+        name: 'test-event',
+      })
+    } finally {
+      performanceNowSpy.mockRestore()
+      recordSpy.mockRestore()
+    }
+  })
 })

src/internal/queue/event.ts

@@ -281,7 +281,7 @@ export class Event<T extends Omit<BasePayload, '$version'>> {
       }
     }
 
-    const startTime = process.hrtime.bigint()
+    const startTime = performance.now()
     const sendOptions = eventClass.getSendOptions(this.payload) || {}
 
     if (this.payload.scheduleAt) {
@@ -360,7 +360,7 @@ export class Event<T extends Omit<BasePayload, '$version'>> {
         },
       })
     } finally {
-      const duration = Number(process.hrtime.bigint() - startTime) / 1e9
+      const duration = (performance.now() - startTime) / 1000
       queueJobSchedulingTime.record(duration, {
         name: eventClass.getQueueName(),
       })

src/storage/database/pg.test.ts

@@ -10,6 +10,10 @@ class TestStoragePgDB extends StoragePgDB {
     return this.runUnscopedQuery('MetricWithoutTenantAttribute', async () => 'ok')
   }
 
+  runScopedMetricProbe(): Promise<string> {
+    return this.runQuery('ScopedMetricDuration', async () => 'ok')
+  }
+
   runErrorMappingProbe(): Promise<unknown> {
     return this.runQuery('FindBucketById', (db) => {
       return this.query(db, 'SELECT * FROM storage.buckets WHERE id = $1')
@@ -47,18 +51,59 @@ describe('StoragePgDB metrics', () => {
       host: 'localhost',
     })
     const recordSpy = vi.spyOn(dbQueryPerformance, 'record')
+    const performanceNowSpy = vi
+      .spyOn(performance, 'now')
+      .mockReturnValueOnce(10)
+      .mockReturnValueOnce(15)
 
     try {
       await expect(storage.runMetricProbe()).resolves.toBe('ok')
 
-      expect(recordSpy).toHaveBeenCalledWith(expect.any(Number), {
+      expect(recordSpy).toHaveBeenCalledWith(0.005, {
         name: 'MetricWithoutTenantAttribute',
         requestAborted: false,
         requestAbortedBeforeStart: false,
         requestAbortedAfterStart: false,
       })
       expect(recordSpy.mock.calls[0]?.[1]).not.toHaveProperty('tenantId')
     } finally {
+      performanceNowSpy.mockRestore()
+      recordSpy.mockRestore()
+    }
+  })
+
+  test('records scoped DB query duration from numeric monotonic timestamps', async () => {
+    const transaction = {
+      commit: vi.fn(),
+      rollback: vi.fn(),
+      isCompleted: vi.fn().mockReturnValue(false),
+    }
+    const connection = {
+      getAbortSignal: vi.fn().mockReturnValue(undefined),
+      transaction: vi.fn().mockResolvedValue(transaction),
+      setScope: vi.fn(),
+    } as unknown as PgTenantConnection
+    const storage = new TestStoragePgDB(connection, {
+      tenantId: 'metric-cardinality-tenant',
+      host: 'localhost',
+    })
+    const recordSpy = vi.spyOn(dbQueryPerformance, 'record')
+    const performanceNowSpy = vi
+      .spyOn(performance, 'now')
+      .mockReturnValueOnce(2)
+      .mockReturnValueOnce(9)
+
+    try {
+      await expect(storage.runScopedMetricProbe()).resolves.toBe('ok')
+
+      expect(recordSpy).toHaveBeenCalledWith(0.007, {
+        name: 'ScopedMetricDuration',
+        requestAborted: false,
+        requestAbortedBeforeStart: false,
+        requestAbortedAfterStart: false,
+      })
+    } finally {
+      performanceNowSpy.mockRestore()
       recordSpy.mockRestore()
     }
   })

src/storage/database/pg.ts

@@ -1754,7 +1754,7 @@ export class StoragePgDB implements Database {
     queryName: string,
     fn: (db: PgExecutor, signal?: AbortSignal) => Promise<T>
   ): Promise<T> {
-    const startTime = process.hrtime.bigint()
+    const startTime = performance.now()
     const abortSignal = this.connection.getAbortSignal()
     const recordDuration = this.createDurationRecorder(queryName, startTime, abortSignal)
 
@@ -1885,7 +1885,7 @@ export class StoragePgDB implements Database {
     queryName: string,
     fn: (db: PgExecutor, signal?: AbortSignal) => Promise<T>
   ): Promise<T> {
-    const startTime = process.hrtime.bigint()
+    const startTime = performance.now()
     const abortSignal = this.connection.getAbortSignal()
     const recordDuration = this.createDurationRecorder(queryName, startTime, abortSignal)
 
@@ -1912,13 +1912,13 @@ export class StoragePgDB implements Database {
 
   private createDurationRecorder(
     queryName: string,
-    startTime: bigint,
+    startTime: number,
     abortSignal?: AbortSignal
   ): () => void {
     const requestAbortedBeforeStart = Boolean(abortSignal?.aborted)
 
     return () => {
-      const duration = Number(process.hrtime.bigint() - startTime) / 1e9
+      const duration = (performance.now() - startTime) / 1000
       // This intentionally reads the signal after the query work settles. The
       // attributes describe request abort observation, not proof that PostgreSQL
       // cancelled this specific statement.