Console Tracer Summary

packages/sdk/src/appChain/AppChain.ts

@@ -24,7 +24,6 @@ import {
   NetworkStateTransportModule,
   DummyStateService,
   WorkerReadyModule,
-  ConsoleLoggingFactory,
 } from "@proto-kit/sequencer";
 import {
   NetworkState,
@@ -315,7 +314,6 @@ export class AppChain<
 
     this.useDependencyFactory(AreProofsEnabledFactory);
     this.useDependencyFactory(SharedDependencyFactory);
-    this.useDependencyFactory(ConsoleLoggingFactory);
 
     this.container
       .resolve<AreProofsEnabled>("AreProofsEnabled")

packages/sequencer/package.json

@@ -32,11 +32,12 @@
     "@types/node": "^20.2.5"
   },
   "dependencies": {
+    "ascii-table3": "^0.9.0",
     "compute-gcd": "^1.2.1",
     "lodash-es": "^4.17.21",
+    "mina-fungible-token": "^1.0.0",
     "reflect-metadata": "^0.1.13",
-    "ts-pattern": "^4.3.0",
-    "mina-fungible-token": "^1.0.0"
+    "ts-pattern": "^4.3.0"
   },
   "gitHead": "397881ed5d8f98f5005bcd7be7f5a12b3bc6f956"
 }

packages/sequencer/src/index.ts

@@ -106,5 +106,5 @@ export * from "./settlement/transactions/MinaTransactionSimulator";
 export * from "./settlement/transactions/MinaSimulationService";
 export * from "./logging/Tracer";
 export * from "./logging/trace";
-export * from "./logging/ConsoleLoggingFactory";
+export * from "./logging/ConsoleTracingFactory";
 export * from "./logging/ConsoleTracer";

packages/sequencer/src/logging/ConsoleTracer.ts

@@ -1,23 +1,104 @@
 import { injectable } from "tsyringe";
 import { log } from "@proto-kit/common";
+import { AsciiTable3 } from "ascii-table3";
+// eslint-disable-next-line import/no-extraneous-dependencies
+import sortBy from "lodash/sortBy";
+
+import { closeable } from "../sequencer/builder/Closeable";
 
 import { Tracer } from "./Tracer";
 
+type StoreType = Record<string, { duration: number }[]>;
+
 @injectable()
+@closeable()
 export class ConsoleTracer implements Tracer {
+  // Hard-code this for the moment. Needs to be configured.
+  timeInterval: number = 8000;
+
+  store: StoreType = {};
+
+  type: "interval" | "manual" = "interval";
+
+  public enableManualOutputs() {
+    this.type = "manual";
+    this.clearInterval();
+  }
+
+  intervalId: NodeJS.Timeout | undefined = undefined;
+
+  public getTraces() {
+    return this.store;
+  }
+
+  public clearTraces() {
+    this.store = {};
+  }
+
+  public printSummary() {
+    const { store } = this;
+    const traceNames = Object.keys(store);
+
+    // We checked the record to see if any methods have exceeded the configured interval.
+    // If so we print them and then delete from the record.
+    // We look at the first element in the array only (i.e. the first invocation of the function)
+    // as this should be enough.
+    const rows = traceNames.map((traceName) => {
+      const sumTime = store[traceName].reduce((result, curr) => {
+        return result + curr.duration;
+      }, 0);
+      const numberOfCalls = store[traceName].length;
+      const avg = (sumTime / numberOfCalls).toFixed(2);
+      return [traceName, numberOfCalls, avg, sumTime.toFixed(0)];
+    });
+
+    const sortedRows = sortBy(rows, ([name]) => name);
+
+    const table = new AsciiTable3()
+      .setHeading("Trace", "# calls", "avg", "sum")
+      .setAlignLeft(1)
+      .setAlignRight(2)
+      .setAlignRight(3)
+      .setAlignRight(4)
+      .setStyle("compact")
+      .addRowMatrix(sortedRows);
+
+    log.debug(table.toString());
+
+    this.clearTraces();
+  }
+
   public async trace<T>(
     name: string,
     f: () => Promise<T>,
     metadata?: Record<string, string | number | boolean>
   ): Promise<T> {
-    const timeStart = Date.now();
+    if (this.intervalId === undefined && this.type === "interval") {
+      this.intervalId = setInterval(
+        () => this.printSummary(),
+        this.timeInterval
+      );
+    }
+
+    const startTime = Date.now();
     const result = await f();
-    const message = `Routine ${name} took ${Date.now() - timeStart}ms`;
-    if (metadata !== undefined) {
-      log.debug(message, metadata);
+    const duration = Date.now() - startTime;
+
+    if (name in this.store) {
+      this.store[name].push({ duration });
     } else {
-      log.debug(message);
+      this.store[name] = [{ duration }];
     }
     return result;
   }
+
+  private clearInterval() {
+    if (this.intervalId !== undefined) {
+      clearInterval(this.intervalId);
+    }
+  }
+
+  public async close() {
+    this.clearInterval();
+  }
 }

packages/sequencer/src/logging/ConsoleLoggingFactory.ts → packages/sequencer/src/logging/ConsoleTracingFactory.ts

@@ -2,7 +2,7 @@ import { DependencyRecord } from "@proto-kit/common";
 
 import { ConsoleTracer } from "./ConsoleTracer";
 
-export class ConsoleLoggingFactory {
+export class ConsoleTracingFactory {
   public static dependencies() {
     return {
       Tracer: {

packages/sequencer/src/sequencer/executor/Sequencer.ts

@@ -4,6 +4,7 @@ import {
   TypedClass,
   ModuleContainerDefinition,
   log,
+  ChildContainerProvider,
 } from "@proto-kit/common";
 import {
   Runtime,
@@ -17,10 +18,11 @@ import {
 } from "@proto-kit/protocol";
 import { DependencyContainer, injectable } from "tsyringe";
 
-import { SequencerModule } from "../builder/SequencerModule";
-import { Closeable } from "../builder/Closeable";
+import { sequencerModule, SequencerModule } from "../builder/SequencerModule";
+import { closeable, Closeable } from "../builder/Closeable";
 
 import { Sequenceable } from "./Sequenceable";
+import { ConsoleTracingFactory } from "../../logging/ConsoleTracingFactory";
 
 export type SequencerModulesRecord = ModulesRecord<
   TypedClass<SequencerModule<unknown>>
@@ -62,6 +64,11 @@ export class Sequencer<Modules extends SequencerModulesRecord>
     return this.container;
   }
 
+  public create(childContainerProvider: ChildContainerProvider) {
+    super.create(childContainerProvider);
+    this.useDependencyFactory(ConsoleTracingFactory);
+  }
+
   /**
    * Starts the sequencer by iterating over all provided
    * modules to start each

packages/sequencer/test-integration/benchmarks/tps.test.ts

@@ -23,6 +23,7 @@ import { afterEach } from "@jest/globals";
 
 import {
   BlockProducerModule,
+  ConsoleTracer,
   DatabasePruneModule,
   ManualBlockTrigger,
   Sequencer,
@@ -124,10 +125,11 @@ export async function createAppChain() {
 
 const timeout = 600000;
 
-describe.skip("tps", () => {
+describe("tps", () => {
   let appChain: Awaited<ReturnType<typeof createAppChain>>;
   let privateKeys: PrivateKey[] = [];
   let balances: Balances;
+  let tracer: ConsoleTracer;
 
   async function mint(signer: PrivateKey, amount: number, nonce: number = 0) {
     appChain.resolve("Signer").config.signer = signer;
@@ -171,8 +173,10 @@ describe.skip("tps", () => {
 
       balances = appChain.runtime.resolve("Balances");
 
+      tracer = appChain.sequencer.resolve("Tracer") as ConsoleTracer;
+      tracer.enableManualOutputs();
+
       await fundKeys(200);
-      // log.enableTiming();
     } catch (e) {
       console.error(e);
       throw e;
@@ -233,6 +237,8 @@ describe.skip("tps", () => {
         return await appChain.sequencer.resolve("BlockTrigger").produceBlock();
       });
 
+      tracer.printSummary();
+
       console.log("txs", produceBlockDuration.result?.transactions.length);
 
       const tps = transactionCount / (produceBlockDuration.duration / 1000);