[DNM] Add logOperationTime util with implementation in protocol module

modules/protocol/src/vector.ts

@@ -20,7 +20,7 @@ import {
   ProtocolError,
   jsonifyError,
 } from "@connext/vector-types";
-import { getCreate2MultisigAddress, getRandomBytes32 } from "@connext/vector-utils";
+import { getCreate2MultisigAddress, getRandomBytes32, logOperationTime } from "@connext/vector-utils";
 import { Evt } from "evt";
 import pino from "pino";
 
@@ -132,6 +132,7 @@ export class Vector implements IVectorProtocol {
   ): Promise<Result<FullChannelState, OutboundChannelUpdateError>> {
     const method = "executeUpdate";
     const methodId = getRandomBytes32();
+    const label = logOperationTime(this.logger, method);
     this.logger.debug({
       method,
       methodId,
@@ -178,6 +179,7 @@ export class Vector implements IVectorProtocol {
       );
     }
 
+    logOperationTime(this.logger, method, label);
     return outboundRes;
   }
 
@@ -199,7 +201,7 @@ export class Vector implements IVectorProtocol {
         }
         const method = "onReceiveProtocolMessage";
         const methodId = getRandomBytes32();
-        this.logger.debug({ method, methodId }, "Method start");
+        const label = logOperationTime(this.logger, method);
 
         if (msg.isError) {
           this.logger.error(
@@ -267,7 +269,7 @@ export class Vector implements IVectorProtocol {
           updatedTransfers: updatedActiveTransfers,
           updatedTransfer,
         });
-        this.logger.debug({ method, methodId }, "Method complete");
+        logOperationTime(this.logger, method, label);
       },
     );
 
@@ -355,7 +357,7 @@ export class Vector implements IVectorProtocol {
   public async setup(params: ProtocolParams.Setup): Promise<Result<FullChannelState, OutboundChannelUpdateError>> {
     const method = "setup";
     const methodId = getRandomBytes32();
-    this.logger.debug({ method, methodId }, "Method start");
+    const label = logOperationTime(this.logger, method);
     // Validate all parameters
     const error = this.validateParamSchema(params, ProtocolParams.SetupSchema);
     if (error) {
@@ -400,14 +402,15 @@ export class Vector implements IVectorProtocol {
       },
       "Method complete",
     );
+    logOperationTime(this.logger, method, label);
     return returnVal;
   }
 
   // Adds a deposit that has *already occurred* onchain into the multisig
   public async deposit(params: ProtocolParams.Deposit): Promise<Result<FullChannelState, OutboundChannelUpdateError>> {
     const method = "deposit";
     const methodId = getRandomBytes32();
-    this.logger.debug({ method, methodId }, "Method start");
+    const label = logOperationTime(this.logger, method);
     // Validate all input
     const error = this.validateParamSchema(params, ProtocolParams.DepositSchema);
     if (error) {

modules/utils/src/logOperationTime.ts

@@ -0,0 +1,33 @@
+import pino from "pino";
+import { performance } from 'perf_hooks';
+import { getRandomBytes32 } from "@connext/vector-utils";
+
+/// This method is used to log the start and end time of an executed method. We are using the
+/// perf_hooks (performance) lib provided by node to calculate this - much more accurate than
+/// Date.now(). On first call, a unique label string is generated and returned. On second call,
+/// same label string should be passed in to measure and log the diff in time (i.e. amount of
+/// time method took to execute in ms).
+export const logOperationTime = (log: pino.BaseLogger, method: string, label?: string): string => {
+  if (label) {
+    const stopLabel = `${label}-stop`;
+    const timestamp = performance.mark(stopLabel);
+    const diff = performance.measure(method, label, stopLabel);
+    const message = `${method} : finished @ ${timestamp}; took ${diff} ms`;
+    // Depending on how long method took, up severity of logging call. This is a default
+    // arrangement that was copied over from indra.
+    if (diff < 2) {
+      log.debug(message);
+    } else if (diff < 200) {
+      log.info(message);
+    } else {
+      log.warn(message);
+    }
+  } else {
+    // Generate the label we'll be using (for later ref) using unique hexstring.
+    const label = `${method}-${getRandomBytes32()}`;
+    performance.mark(label);
+    const message = `${method}: started`;
+    log.debug(message);
+  }
+  return label;
+};