feat(localenv): add performance metrics

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: 'psql_get_account_balances'
+  })
   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: 'psql_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: 'tb_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,13 +440,25 @@ export const depositOutgoingPaymentLiquidity: MutationResolvers<ApolloContext>['
     args,
     ctx
   ): Promise<ResolversTypes['LiquidityMutationResponse']> => {
+    const telemetry = await ctx.container.use('telemetry')
+    const stopTimer = telemetry.startTimer(
+      'deposit_outgoing_payment_liquidity_ms',
+      {
+        callName: 'depositOutgoingPaymentLiquidity'
+      }
+    )
     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)) {
+      stopTimer()
       throw new GraphQLError(errorToMessage[LiquidityError.InvalidId], {
         extensions: {
           code: errorToCode[LiquidityError.InvalidId]
@@ -455,23 +467,31 @@ export const depositOutgoingPaymentLiquidity: MutationResolvers<ApolloContext>['
     }
 
     if (!event.data.debitAmount) {
+      stopTimer()
       throw new Error('No debit amount')
     }
     const outgoingPaymentService = await ctx.container.use(
       'outgoingPaymentService'
     )
+    const stopTimerFund = telemetry.startTimer('fund_payment_ms', {
+      callName: 'outgoingPaymentService.fund'
+    })
     const paymentOrErr = await outgoingPaymentService.fund({
       id: outgoingPaymentId,
       amount: BigInt(event.data.debitAmount.value),
       transferId: event.id
     })
+    stopTimerFund()
+
     if (isFundingError(paymentOrErr)) {
+      stopTimer()
       throw new GraphQLError(fundingErrorToMessage[paymentOrErr], {
         extensions: {
           code: fundingErrorToCode[paymentOrErr]
         }
       })
     }
+    stopTimer()
     return {
       success: true
     }

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 (ILP)'
+  })
   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: '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: '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: 'opLifecycle_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(