feat(localenv): add performance metrics

localenv/telemetry/otel-collector-config.yaml

@@ -8,8 +8,6 @@ processors:
   batch:
 
 exporters:
-  logging:
-    loglevel: info
   debug:
     verbosity: detailed
   prometheus:

packages/backend/src/accounting/psql/balance.test.ts

@@ -24,7 +24,8 @@ describe('Balances', (): void => {
     appContainer = await createTestApp(deps)
     serviceDeps = {
       logger: await deps.use('logger'),
-      knex: await deps.use('knex')
+      knex: await deps.use('knex'),
+      telemetry: await deps.use('telemetry')
     }
     knex = appContainer.knex
   })

packages/backend/src/accounting/psql/balance.ts

@@ -14,6 +14,9 @@ export async function getAccountBalances(
   account: LedgerAccount,
   trx?: TransactionOrKnex
 ): Promise<AccountBalance> {
+  const stopTimer = deps.telemetry.startTimer('psql_get_account_balances', {
+    callName: 'AccountingService:Postgres:getAccountBalances'
+  })
   try {
     const queryResult = await (trx ?? deps.knex).raw(
       `
@@ -54,5 +57,7 @@ export async function getAccountBalances(
     )
 
     throw err
+  } finally {
+    stopTimer()
   }
 }

packages/backend/src/accounting/psql/ledger-account/index.test.ts

@@ -25,7 +25,8 @@ describe('Ledger Account', (): void => {
     appContainer = await createTestApp(deps)
     serviceDeps = {
       logger: await deps.use('logger'),
-      knex: await deps.use('knex')
+      knex: await deps.use('knex'),
+      telemetry: await deps.use('telemetry')
     }
     knex = appContainer.knex
   })

packages/backend/src/accounting/psql/ledger-transfer/index.test.ts

@@ -34,7 +34,8 @@ describe('Ledger Transfer', (): void => {
     appContainer = await createTestApp(deps)
     serviceDeps = {
       logger: await deps.use('logger'),
-      knex: await deps.use('knex')
+      knex: await deps.use('knex'),
+      telemetry: await deps.use('telemetry')
     }
     knex = appContainer.knex
   })

packages/backend/src/accounting/psql/service.ts

@@ -34,9 +34,11 @@ import {
   getAccountTransfers
 } from './ledger-transfer'
 import { LedgerTransfer, LedgerTransferType } from './ledger-transfer/model'
+import { TelemetryService } from '../../telemetry/service'
 
 export interface ServiceDependencies extends BaseService {
   knex: TransactionOrKnex
+  telemetry: TelemetryService
   withdrawalThrottleDelay?: number
 }
 
@@ -145,13 +147,24 @@ export async function getAccountTotalSent(
   deps: ServiceDependencies,
   accountRef: string
 ): Promise<bigint | undefined> {
+  const stopTimer = deps.telemetry.startTimer(
+    'psql_get_account_total_sent_ms',
+    {
+      callName: 'AccountingService:Postgres:getAccountTotalSent'
+    }
+  )
   const account = await getLiquidityAccount(deps, accountRef)
 
   if (!account) {
+    stopTimer()
     return
   }
 
-  return (await getAccountBalances(deps, account)).debitsPosted
+  const totalsSent = (await getAccountBalances(deps, account)).debitsPosted
+
+  stopTimer()
+
+  return totalsSent
 }
 
 export async function getAccountsTotalSent(

packages/backend/src/accounting/tigerbeetle/service.ts

@@ -31,6 +31,7 @@ import {
   getAccountTransfers
 } from './transfers'
 import { toTigerBeetleId } from './utils'
+import { TelemetryService } from '../../telemetry/service'
 
 export enum TigerBeetleAccountCode {
   LIQUIDITY_WEB_MONETIZATION = 1,
@@ -68,6 +69,7 @@ export const convertToTigerBeetleTransferCode: {
 
 export interface ServiceDependencies extends BaseService {
   tigerBeetle: Client
+  telemetry: TelemetryService
   withdrawalThrottleDelay?: number
 }
 
@@ -218,10 +220,15 @@ export async function getAccountTotalSent(
   deps: ServiceDependencies,
   id: string
 ): Promise<bigint | undefined> {
+  const stopTimer = deps.telemetry.startTimer('tb_get_account_total_sent_ms', {
+    callName: 'AccountingService:Tigerbeetle:getAccountTotalSent'
+  })
   const account = (await getAccounts(deps, [id]))[0]
   if (account) {
+    stopTimer()
     return account.debits_posted
   }
+  stopTimer()
 }
 
 export async function getAccountsTotalSent(

packages/backend/src/graphql/resolvers/liquidity.ts

@@ -440,40 +440,66 @@ export const depositOutgoingPaymentLiquidity: MutationResolvers<ApolloContext>['
     args,
     ctx
   ): Promise<ResolversTypes['LiquidityMutationResponse']> => {
-    const { outgoingPaymentId } = args.input
-    const webhookService = await ctx.container.use('webhookService')
-    const event = await webhookService.getLatestByResourceId({
-      outgoingPaymentId,
-      types: [OutgoingPaymentDepositType.PaymentCreated]
-    })
-    if (!event || !isOutgoingPaymentEvent(event)) {
-      throw new GraphQLError(errorToMessage[LiquidityError.InvalidId], {
-        extensions: {
-          code: errorToCode[LiquidityError.InvalidId]
-        }
+    const telemetry = await ctx.container.use('telemetry')
+    const stopTimer = telemetry.startTimer(
+      'deposit_outgoing_payment_liquidity_ms',
+      {
+        callName: 'Resolver:depositOutgoingPaymentLiquidity'
+      }
+    )
+
+    try {
+      const { outgoingPaymentId } = args.input
+      const webhookService = await ctx.container.use('webhookService')
+      const stopTimerWh = telemetry.startTimer('wh_get_latest_ms', {
+        callName: 'WebhookService:getLatestByResourceId'
       })
-    }
+      const event = await webhookService.getLatestByResourceId({
+        outgoingPaymentId,
+        types: [OutgoingPaymentDepositType.PaymentCreated]
+      })
+      stopTimerWh()
+      if (!event || !isOutgoingPaymentEvent(event)) {
+        throw new GraphQLError(errorToMessage[LiquidityError.InvalidId], {
+          extensions: {
+            code: errorToCode[LiquidityError.InvalidId]
+          }
+        })
+      }
 
-    if (!event.data.debitAmount) {
-      throw new Error('No debit amount')
-    }
-    const outgoingPaymentService = await ctx.container.use(
-      'outgoingPaymentService'
-    )
-    const paymentOrErr = await outgoingPaymentService.fund({
-      id: outgoingPaymentId,
-      amount: BigInt(event.data.debitAmount.value),
-      transferId: event.id
-    })
-    if (isFundingError(paymentOrErr)) {
-      throw new GraphQLError(fundingErrorToMessage[paymentOrErr], {
-        extensions: {
-          code: fundingErrorToCode[paymentOrErr]
-        }
+      if (!event.data.debitAmount) {
+        throw new Error('No debit amount')
+      }
+      const outgoingPaymentService = await ctx.container.use(
+        'outgoingPaymentService'
+      )
+      const stopTimerFund = telemetry.startTimer('fund_payment_ms', {
+        callName: 'OutgoingPaymentService:fund'
       })
-    }
-    return {
-      success: true
+      const paymentOrErr = await outgoingPaymentService.fund({
+        id: outgoingPaymentId,
+        amount: BigInt(event.data.debitAmount.value),
+        transferId: event.id
+      })
+      stopTimerFund()
+
+      if (isFundingError(paymentOrErr)) {
+        throw new GraphQLError(fundingErrorToMessage[paymentOrErr], {
+          extensions: {
+            code: fundingErrorToCode[paymentOrErr]
+          }
+        })
+      }
+      return {
+        success: true
+      }
+      // Not a useless catch. Wrapped resolver in try and simply re-throwing
+      // errors to enforce stopTimer always being called once at end of the resolver
+      // eslint-disable-next-line no-useless-catch
+    } catch (err) {
+      throw err
+    } finally {
+      stopTimer()
     }
   }
 

packages/backend/src/index.ts

@@ -215,6 +215,7 @@ export function initIocContainer(
     const logger = await deps.use('logger')
     const knex = await deps.use('knex')
     const config = await deps.use('config')
+    const telemetry = await deps.use('telemetry')
 
     if (config.useTigerBeetle) {
       container.singleton('tigerBeetle', async (deps) => {
@@ -231,14 +232,16 @@ export function initIocContainer(
         logger,
         knex,
         tigerBeetle,
-        withdrawalThrottleDelay: config.withdrawalThrottleDelay
+        withdrawalThrottleDelay: config.withdrawalThrottleDelay,
+        telemetry
       })
     }
 
     return createPsqlAccountingService({
       logger,
       knex,
-      withdrawalThrottleDelay: config.withdrawalThrottleDelay
+      withdrawalThrottleDelay: config.withdrawalThrottleDelay,
+      telemetry
     })
   })
   container.singleton('peerService', async (deps) => {
@@ -346,7 +349,8 @@ export function initIocContainer(
       walletAddressService: await deps.use('walletAddressService'),
       remoteIncomingPaymentService: await deps.use(
         'remoteIncomingPaymentService'
-      )
+      ),
+      telemetry: await deps.use('telemetry')
     })
   })
 
@@ -450,7 +454,10 @@ export function initIocContainer(
       receiverService: await deps.use('receiverService'),
       feeService: await deps.use('feeService'),
       walletAddressService: await deps.use('walletAddressService'),
-      paymentMethodHandlerService: await deps.use('paymentMethodHandlerService')
+      paymentMethodHandlerService: await deps.use(
+        'paymentMethodHandlerService'
+      ),
+      telemetry: await deps.use('telemetry')
     })
   })
 

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

@@ -76,23 +76,22 @@ export async function handleSending(
     throw LifecycleError.BadState
   }
 
-  const payStartTime = Date.now()
+  const stopTimer = deps.telemetry.startTimer('ilp_pay_time_ms', {
+    description: 'Time to complete an ILP payment',
+    callName: 'PaymentMethodHandlerService:pay'
+  })
   await deps.paymentMethodHandlerService.pay('ILP', {
     receiver,
     outgoingPayment: payment,
     finalDebitAmount: maxDebitAmount,
     finalReceiveAmount: maxReceiveAmount
   })
-  const payEndTime = Date.now()
+  stopTimer()
 
-  const payDuration = payEndTime - payStartTime
   await Promise.all([
     deps.telemetry.incrementCounter('transactions_total', 1, {
       description: 'Count of funded transactions'
     }),
-    deps.telemetry.recordHistogram('ilp_pay_time_ms', payDuration, {
-      description: 'Time to complete an ILP payment'
-    }),
     deps.telemetry.incrementCounterWithTransactionAmountDifference(
       'transaction_fee_amounts',
       payment.sentAmount,
@@ -142,17 +141,24 @@ export async function handleFailed(
   payment: OutgoingPayment,
   error: string
 ): Promise<void> {
+  const stopTimer = deps.telemetry.startTimer('handle_failed_ms', {
+    callName: 'OutgoingPaymentLifecycle:handleFailed'
+  })
   await payment.$query(deps.knex).patch({
     state: OutgoingPaymentState.Failed,
     error
   })
   await sendWebhookEvent(deps, payment, OutgoingPaymentEventType.PaymentFailed)
+  stopTimer()
 }
 
 async function handleCompleted(
   deps: ServiceDependencies,
   payment: OutgoingPayment
 ): Promise<void> {
+  const stopTimer = deps.telemetry.startTimer('handle_completed_ms', {
+    callName: 'OutgoingPaymentLifecycle:handleCompleted'
+  })
   await payment.$query(deps.knex).patch({
     state: OutgoingPaymentState.Completed
   })
@@ -162,6 +168,7 @@ async function handleCompleted(
     payment,
     OutgoingPaymentEventType.PaymentCompleted
   )
+  stopTimer()
 }
 
 export async function sendWebhookEvent(
@@ -170,6 +177,9 @@ export async function sendWebhookEvent(
   type: OutgoingPaymentEventType,
   trx?: TransactionOrKnex
 ): Promise<void> {
+  const stopTimer = deps.telemetry.startTimer('op_send_webhook_event_ms', {
+    callName: 'OutgoingPaymentLifecycle:sendWebhookEvent'
+  })
   // TigerBeetle accounts are only created as the OutgoingPayment is funded.
   // So default the amountSent and balance to 0 for outgoing payments still in the funding state
   const amountSent =
@@ -182,6 +192,7 @@ export async function sendWebhookEvent(
       : await deps.accountingService.getBalance(payment.id)
 
   if (amountSent === undefined || balance === undefined) {
+    stopTimer()
     throw LifecycleError.MissingBalance
   }
 
@@ -199,6 +210,7 @@ export async function sendWebhookEvent(
     data: payment.toData({ amountSent, balance }),
     withdrawal
   })
+  stopTimer()
 }
 
 function validateAssets(