feat: transaction time histogram metric (#2787)

* feat: WIP telemetry

* chore: rm commented out code

* chore: histogram tests, rm comments

* fix: test mock

* feat(backend): add types to tel service maps

* feat(backend): change pay time metric to ilp from outgoing payment

* docs: add details for new ilp pay metric

* Update packages/documentation/src/content/docs/telemetry/overview.md

Co-authored-by: Max Kurapov <max@interledger.org>

* docs(backend): update for new histogram metric

---------

Co-authored-by: Max Kurapov <max@interledger.org>

packages/backend/src/open_payments/payment/outgoing/lifecycle.ts

@@ -75,19 +75,32 @@ export async function handleSending(
     throw LifecycleError.BadState
   }
 
+  const payStartTime = Date.now()
   await deps.paymentMethodHandlerService.pay('ILP', {
     receiver,
     outgoingPayment: payment,
     finalDebitAmount: maxDebitAmount,
     finalReceiveAmount: maxReceiveAmount
   })
-  deps.telemetry
-    ?.getOrCreateMetric('transactions_total', {
-      description: 'Count of funded transactions'
-    })
-    .add(1, {
-      source: deps.telemetry.getInstanceName()
-    })
+  const payEndTime = Date.now()
+
+  if (deps.telemetry) {
+    deps.telemetry
+      .getOrCreateMetric('transactions_total', {
+        description: 'Count of funded transactions'
+      })
+      .add(1, {
+        source: deps.telemetry.getInstanceName()
+      })
+    const payDuration = payEndTime - payStartTime
+    deps.telemetry
+      .getOrCreateHistogramMetric('ilp_pay_time_ms', {
+        description: 'Time to complete an ILP payment'
+      })
+      .record(payDuration, {
+        source: deps.telemetry.getInstanceName()
+      })
+  }
 
   await handleCompleted(deps, payment)
 }

packages/backend/src/telemetry/service.test.ts

@@ -4,15 +4,16 @@ import { AppServices } from '../app'
 import { Config } from '../config/app'
 import { ConvertError, RatesService } from '../rates/service'
 import { TestContainer, createTestApp } from '../tests/app'
-import { mockCounter } from '../tests/telemetry'
+import { mockCounter, mockHistogram } from '../tests/telemetry'
 import { TelemetryService } from './service'
 
 jest.mock('@opentelemetry/api', () => ({
   ...jest.requireActual('@opentelemetry/api'),
   metrics: {
     setGlobalMeterProvider: jest.fn(),
     getMeter: jest.fn().mockReturnValue({
-      createCounter: jest.fn().mockImplementation(() => mockCounter)
+      createCounter: jest.fn().mockImplementation(() => mockCounter),
+      createHistogram: jest.fn().mockImplementation(() => mockHistogram)
     })
   }
 }))
@@ -64,6 +65,19 @@ describe('TelemetryServiceImpl', () => {
     expect(retrievedCounter).toBe(existingCounter)
   })
 
+  it('should create a histogram when getOrCreateHistogramMetric is called for a new metric', () => {
+    const histogram = telemetryService.getOrCreateHistogramMetric('testMetric')
+    expect(histogram).toBe(mockHistogram)
+  })
+
+  it('should return an existing histogram when getOrCreateHistogramMetric is called for an existing metric', () => {
+    const existingHistogram =
+      telemetryService.getOrCreateHistogramMetric('existingMetric')
+    const retrievedHistogram =
+      telemetryService.getOrCreateHistogramMetric('existingMetric')
+    expect(retrievedHistogram).toBe(existingHistogram)
+  })
+
   it('should return the instance name when calling getInstanceName', () => {
     const serviceName = telemetryService.getInstanceName()
 

packages/backend/src/telemetry/service.ts

@@ -1,4 +1,4 @@
-import { Counter, MetricOptions, metrics } from '@opentelemetry/api'
+import { Counter, Histogram, MetricOptions, metrics } from '@opentelemetry/api'
 import { OTLPMetricExporter } from '@opentelemetry/exporter-metrics-otlp-grpc'
 import { Resource } from '@opentelemetry/resources'
 import {
@@ -13,6 +13,7 @@ import { BaseService } from '../shared/baseService'
 export interface TelemetryService {
   shutdown(): void
   getOrCreateMetric(name: string, options?: MetricOptions): Counter
+  getOrCreateHistogramMetric(name: string, options?: MetricOptions): Histogram
   getInstanceName(): string | undefined
   getBaseAssetCode(): string
   getBaseScale(): number
@@ -46,7 +47,8 @@ class TelemetryServiceImpl implements TelemetryService {
   private internalRatesService: RatesService
   private aseRatesService: RatesService
 
-  private counters = new Map()
+  private counters: Map<string, Counter> = new Map()
+  private histograms: Map<string, Histogram> = new Map()
   constructor(private deps: TelemetryServiceDependencies) {
     // debug logger:
     // diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG)
@@ -85,6 +87,24 @@ class TelemetryServiceImpl implements TelemetryService {
     await this.meterProvider?.shutdown()
   }
 
+  private createHistogram(name: string, options: MetricOptions | undefined) {
+    const histogram = metrics
+      .getMeter(METER_NAME)
+      .createHistogram(name, options)
+    this.histograms.set(name, histogram)
+    return histogram
+  }
+  public getOrCreateHistogramMetric(
+    name: string,
+    options?: MetricOptions
+  ): Histogram {
+    const existing = this.histograms.get(name)
+    if (existing) {
+      return existing
+    }
+    return this.createHistogram(name, options)
+  }
+
   private createCounter(
     name: string,
     options: MetricOptions | undefined

packages/backend/src/tests/telemetry.ts

@@ -1,9 +1,15 @@
-import { Attributes, Counter, MetricOptions } from '@opentelemetry/api'
+import {
+  Attributes,
+  Counter,
+  Histogram,
+  MetricOptions
+} from '@opentelemetry/api'
 import { TelemetryService } from '../telemetry/service'
 import { ConvertError, Rates, RatesService } from '../rates/service'
 import { ConvertOptions } from '../rates/util'
 
 export const mockCounter = { add: jest.fn() } as Counter
+export const mockHistogram = { record: jest.fn() } as Histogram
 
 export class MockRatesService implements RatesService {
   async convert(): Promise<bigint | ConvertError> {
@@ -36,6 +42,12 @@ export class MockTelemetryService implements TelemetryService {
   ): Counter<Attributes> {
     return mockCounter
   }
+  public getOrCreateHistogramMetric(
+    _name: string,
+    _options?: MetricOptions | undefined
+  ): Histogram<Attributes> {
+    return mockHistogram
+  }
   public getInstanceName(): string | undefined {
     return 'serviceName'
   }

packages/documentation/src/content/docs/telemetry/overview.md

@@ -60,7 +60,7 @@ If an ASE does not provide the necessary exchange rate for a transaction, the te
 
 ## Instrumentation
 
-Rafiki currently has two counter metrics. All data points (counter increases) are exported to collection endpoints at a configurable interval (default recommended to 15s).
+Rafiki currently has three counter metrics. All data points (counter increases and histogram records) are exported to collection endpoints at a configurable interval (default recommended to 15s).
 
 Currently collected metrics:
 
@@ -70,5 +70,8 @@ Currently collected metrics:
 - `transactions_amount` - Counter metric
   - Description: “Amount sent through the network”.
   - This amount metric increases by the amount sent in each ILP packet.
+- `ilp_pay_time_ms` - Histogram metric
+  - Description: “Time to complete an ILP payment”
+  - This histogram metric records the time taken to make an ILP payment.
 
 **Note**: The current implementation only collects metrics on the SENDING side of a transaction. Metrics for external open-payments transactions RECEIVED by a Rafiki instance in the network are not collected.