diff --git a/package-lock.json b/package-lock.json index 9638f6787..71a2fbe19 100644 --- a/package-lock.json +++ b/package-lock.json @@ -6478,6 +6478,18 @@ "node": ">=0.10.0" } }, + "node_modules/ascii-table3": { + "version": "0.9.0", + "resolved": "https://registry.npmjs.org/ascii-table3/-/ascii-table3-0.9.0.tgz", + "integrity": "sha512-/JcvVCQRTVQHwLI8TCxSeOS9AcCV01MbCJC4plSP5ulygJH+D30lz85nvMcER5k+qoX2fJ1C/i13Zo1/eoMGTw==", + "license": "Apache-2.0", + "dependencies": { + "printable-characters": "^1.0.42" + }, + "engines": { + "node": ">=11.14.0" + } + }, "node_modules/astral-regex": { "version": "2.0.0", "license": "MIT", @@ -18749,6 +18761,12 @@ "url": "https://github.com/chalk/ansi-styles?sponsor=1" } }, + "node_modules/printable-characters": { + "version": "1.0.42", + "resolved": "https://registry.npmjs.org/printable-characters/-/printable-characters-1.0.42.tgz", + "integrity": "sha512-dKp+C4iXWK4vVYZmYSd0KBH5F/h1HoZRsbJ82AVKRO3PEo8L4lBS/vLwhVtpwwuYcoIsVY+1JYKR268yn480uQ==", + "license": "Unlicense" + }, "node_modules/prisma": { "version": "5.21.1", "resolved": "https://registry.npmjs.org/prisma/-/prisma-5.21.1.tgz", @@ -22344,6 +22362,7 @@ "lodash": "^4.17.21", "loglevel": "^1.8.1", "reflect-metadata": "^0.1.13", + "ts-mixer": "^6.0.3", "typescript-memoize": "^1.1.1" }, "devDependencies": { @@ -22590,6 +22609,7 @@ "version": "0.1.1-develop.833+397881ed", "license": "MIT", "dependencies": { + "ascii-table3": "^0.9.0", "compute-gcd": "^1.2.1", "lodash-es": "^4.17.21", "mina-fungible-token": "^1.0.0", diff --git a/packages/sdk/src/appChain/AppChain.ts b/packages/sdk/src/appChain/AppChain.ts index f7f052dbe..31fa4a12d 100644 --- a/packages/sdk/src/appChain/AppChain.ts +++ b/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") diff --git a/packages/sequencer/package.json b/packages/sequencer/package.json index aa2545623..53aebdf45 100644 --- a/packages/sequencer/package.json +++ b/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" } diff --git a/packages/sequencer/src/index.ts b/packages/sequencer/src/index.ts index 4605b4f53..8800bc888 100644 --- a/packages/sequencer/src/index.ts +++ b/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"; diff --git a/packages/sequencer/src/logging/ConsoleTracer.ts b/packages/sequencer/src/logging/ConsoleTracer.ts index 23120eb90..990177d3c 100644 --- a/packages/sequencer/src/logging/ConsoleTracer.ts +++ b/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; + @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( name: string, f: () => Promise, metadata?: Record ): Promise { - 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(); + } } diff --git a/packages/sequencer/src/logging/ConsoleLoggingFactory.ts b/packages/sequencer/src/logging/ConsoleTracingFactory.ts similarity index 87% rename from packages/sequencer/src/logging/ConsoleLoggingFactory.ts rename to packages/sequencer/src/logging/ConsoleTracingFactory.ts index 51678b357..86ad608c3 100644 --- a/packages/sequencer/src/logging/ConsoleLoggingFactory.ts +++ b/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: { diff --git a/packages/sequencer/src/sequencer/executor/Sequencer.ts b/packages/sequencer/src/sequencer/executor/Sequencer.ts index bf41d9768..4a746c8bd 100644 --- a/packages/sequencer/src/sequencer/executor/Sequencer.ts +++ b/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> @@ -62,6 +64,11 @@ export class Sequencer 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 diff --git a/packages/sequencer/test-integration/benchmarks/tps.test.ts b/packages/sequencer/test-integration/benchmarks/tps.test.ts index 32c27c45f..64e22ab13 100644 --- a/packages/sequencer/test-integration/benchmarks/tps.test.ts +++ b/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>; 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);