From 90136f401c24687ed3c8147256684694c40093a2 Mon Sep 17 00:00:00 2001
From: Alan Cruikshanks <alan.cruikshanks@gmail.com>
Date: Tue, 14 Mar 2023 11:48:23 +0000
Subject: [PATCH] Log time taken to process a bill run (#163)

https://eaflood.atlassian.net/browse/WATER-3906

When issues of performance came up in the [charging-module-api](https://github.com/DEFRA/sroc-charging-module-api) we found it immensely useful to have evidence to hand of how long the most contentious process was actually taking.

As we are not in control of the full process with our new SROC supplementary billing process, it would be useful to know exactly how long are part of the journey is taking. We're also about to expand the process to include reversing the previous supplementary bill run. So, it would be useful to get a working idea of how that impacts our timings.

To be clear, this is a very basic metric; the difference between the times at the start and the end of the process. There is no call at this time for factoring the size of a bill run, load on the servers at the time etc. It's all we needed in the Charging Module API, which also means it's some code we can readily steal!
---
 .../process-billing-batch.service.js          | 24 +++++++++++++++++++
 .../process-billing-batch.service.test.js     | 24 +++++++++++++++++++
 2 files changed, 48 insertions(+)

diff --git a/app/services/supplementary-billing/process-billing-batch.service.js b/app/services/supplementary-billing/process-billing-batch.service.js
index 143db79c18..035be53658 100644
--- a/app/services/supplementary-billing/process-billing-batch.service.js
+++ b/app/services/supplementary-billing/process-billing-batch.service.js
@@ -36,6 +36,9 @@ async function go (billingBatch, billingPeriod) {
   const { billingBatchId } = billingBatch
 
   try {
+    // Mark the start time for later logging
+    const startTime = process.hrtime.bigint()
+
     await _updateStatus(billingBatchId, 'processing')
 
     const chargeVersions = await _fetchChargeVersions(billingBatch, billingPeriod)
@@ -59,11 +62,32 @@ async function go (billingBatch, billingPeriod) {
     }
 
     await _finaliseBillingBatch(billingBatch)
+
+    // Log how log the process took
+    _calculateAndLogTime(billingBatchId, startTime)
   } catch (error) {
     global.GlobalNotifier.omfg('Billing Batch process errored', { billingBatch, error })
   }
 }
 
+/**
+   * Log the time taken to process the billing batch
+   *
+   * If `notifier` is not set then it will do nothing. If it is set this will get the current time and then calculate the
+   * difference from `startTime`. This and the `billRunId` are then used to generate a log message.
+   *
+   * @param {string} billingBatchId Id of the billing batch currently being 'processed'
+   * @param {BigInt} startTime The time the generate process kicked off. It is expected to be the result of a call to
+   * `process.hrtime.bigint()`
+   */
+function _calculateAndLogTime (billingBatchId, startTime) {
+  const endTime = process.hrtime.bigint()
+  const timeTakenNs = endTime - startTime
+  const timeTakenMs = timeTakenNs / 1000000n
+
+  global.GlobalNotifier.omg(`Time taken to process billing batch ${billingBatchId}: ${timeTakenMs}ms`)
+}
+
 async function _generateBillingInvoice (chargeVersion, billingBatchId, billingPeriod) {
   try {
     const billingInvoiceData = await GenerateBillingInvoiceService.go(
diff --git a/test/services/supplementary-billing/process-billing-batch.service.test.js b/test/services/supplementary-billing/process-billing-batch.service.test.js
index 1ad42e1fda..5a34e36f49 100644
--- a/test/services/supplementary-billing/process-billing-batch.service.test.js
+++ b/test/services/supplementary-billing/process-billing-batch.service.test.js
@@ -23,6 +23,7 @@ const RegionHelper = require('../../support/helpers/water/region.helper.js')
 
 // Things we need to stub
 const ChargingModuleCreateTransactionService = require('../../../app/services/charging-module/create-transaction.service.js')
+const ChargingModuleGenerateService = require('../../../app/services/charging-module/generate-bill-run.service.js')
 const FetchChargeVersionsService = require('../../../app/services/supplementary-billing/fetch-charge-versions.service.js')
 const GenerateBillingTransactionsService = require('../../../app/services/supplementary-billing/generate-billing-transactions.service.js')
 const HandleErroredBillingBatchService = require('../../../app/services/supplementary-billing/handle-errored-billing-batch.service.js')
@@ -67,6 +68,29 @@ describe('Process billing batch service', () => {
     Sinon.restore()
   })
 
+  describe('when the service is called', () => {
+    beforeEach(() => {
+      Sinon.stub(ChargingModuleCreateTransactionService, 'go').resolves({
+        succeeded: true,
+        response: {
+          body: { transaction: { id: '7e752fa6-a19c-4779-b28c-6e536f028795' } }
+        }
+      })
+      Sinon.stub(ChargingModuleGenerateService, 'go').resolves({
+        succeeded: true,
+        response: {}
+      })
+    })
+
+    it('logs the time taken to process the billing batch', async () => {
+      await ProcessBillingBatchService.go(billingBatch, billingPeriod)
+
+      const logMessage = notifierStub.omg.firstCall.args[0]
+
+      expect(logMessage).to.startWith(`Time taken to process billing batch ${billingBatch.billingBatchId}:`)
+    })
+  })
+
   describe('when the service errors', () => {
     const expectedError = new Error('ERROR')