From 1dfd0eae85aae970571aec62c43951efbdee143b Mon Sep 17 00:00:00 2001 From: ejMina226 <118474890+ejMina226@users.noreply.github.com> Date: Fri, 7 Mar 2025 14:19:08 +0000 Subject: [PATCH 1/7] Start changes for console trace --- packages/sequencer/src/logging/ConsoleTracer.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/packages/sequencer/src/logging/ConsoleTracer.ts b/packages/sequencer/src/logging/ConsoleTracer.ts index 23120eb90..5e085b59e 100644 --- a/packages/sequencer/src/logging/ConsoleTracer.ts +++ b/packages/sequencer/src/logging/ConsoleTracer.ts @@ -5,6 +5,7 @@ import { Tracer } from "./Tracer"; @injectable() export class ConsoleTracer implements Tracer { + // Need some change here to aggregate the same calls. public async trace( name: string, f: () => Promise, From c3e6236c98f09c19ac269d3acfcddb5e08cac107 Mon Sep 17 00:00:00 2001 From: ejMina226 <118474890+ejMina226@users.noreply.github.com> Date: Fri, 7 Mar 2025 15:13:10 +0000 Subject: [PATCH 2/7] Start writing types --- packages/sequencer/src/logging/ConsoleTracer.ts | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/packages/sequencer/src/logging/ConsoleTracer.ts b/packages/sequencer/src/logging/ConsoleTracer.ts index 5e085b59e..b07b38cbf 100644 --- a/packages/sequencer/src/logging/ConsoleTracer.ts +++ b/packages/sequencer/src/logging/ConsoleTracer.ts @@ -1,8 +1,18 @@ -import { injectable } from "tsyringe"; +import { injectable, singleton } from "tsyringe"; import { log } from "@proto-kit/common"; import { Tracer } from "./Tracer"; +type StoreType = { + methodName: string; + invocations: { startTime: number; duration: number }[]; +}; + +@singleton() +export class TraceRecordHolder { + public store?: StoreType; +} + @injectable() export class ConsoleTracer implements Tracer { // Need some change here to aggregate the same calls. From 3340300ba1ed2f5a6ea8d4a2c183ec5c67bce74b Mon Sep 17 00:00:00 2001 From: ejMina226 <118474890+ejMina226@users.noreply.github.com> Date: Fri, 7 Mar 2025 16:09:49 +0000 Subject: [PATCH 3/7] Add in aggregation code. --- .../sequencer/src/logging/ConsoleTracer.ts | 45 ++++++++++++++----- 1 file changed, 33 insertions(+), 12 deletions(-) diff --git a/packages/sequencer/src/logging/ConsoleTracer.ts b/packages/sequencer/src/logging/ConsoleTracer.ts index b07b38cbf..887196e63 100644 --- a/packages/sequencer/src/logging/ConsoleTracer.ts +++ b/packages/sequencer/src/logging/ConsoleTracer.ts @@ -1,33 +1,54 @@ -import { injectable, singleton } from "tsyringe"; +import { injectable, singleton, container } from "tsyringe"; import { log } from "@proto-kit/common"; import { Tracer } from "./Tracer"; -type StoreType = { - methodName: string; - invocations: { startTime: number; duration: number }[]; -}; +type StoreType = Record; @singleton() export class TraceRecordHolder { - public store?: StoreType; + public store: StoreType = {}; } @injectable() export class ConsoleTracer implements Tracer { - // Need some change here to aggregate the same calls. + // Hard-code this for the moment. Needs to be configured. + timeInterval: number = 8000; + public async trace( name: string, f: () => Promise, metadata?: Record ): Promise { - const timeStart = Date.now(); + const store = container.resolve(TraceRecordHolder); + const methodsAlreadyLogged = Object.keys(store.store); + + methodsAlreadyLogged.forEach((methodName) => { + if ( + Date.now() - store.store[methodName][0].startTime > + this.timeInterval + ) { + const sumTime = store.store[methodName].reduce((result, curr) => { + return result + curr.duration; + }, 0); + const numberOfCalls = store.store[methodName].length; + const message = `Routine ${name}: executed ${numberOfCalls} times, average ${sumTime / numberOfCalls}ms`; + if (metadata !== undefined) { + log.debug(message, metadata); + } else { + log.debug(message); + } + delete store.store[methodName]; + } + }); + + 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 store.store) { + store.store[name].push({ startTime, duration }); } else { - log.debug(message); + store.store[name] = [{ startTime, duration }]; } return result; } From 26805359a631c3ab10d3961fab85a12510f16ab9 Mon Sep 17 00:00:00 2001 From: ejMina226 <118474890+ejMina226@users.noreply.github.com> Date: Fri, 7 Mar 2025 16:14:50 +0000 Subject: [PATCH 4/7] Fix typo --- packages/sequencer/src/logging/ConsoleTracer.ts | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/packages/sequencer/src/logging/ConsoleTracer.ts b/packages/sequencer/src/logging/ConsoleTracer.ts index 887196e63..623d76f07 100644 --- a/packages/sequencer/src/logging/ConsoleTracer.ts +++ b/packages/sequencer/src/logging/ConsoleTracer.ts @@ -32,12 +32,8 @@ export class ConsoleTracer implements Tracer { return result + curr.duration; }, 0); const numberOfCalls = store.store[methodName].length; - const message = `Routine ${name}: executed ${numberOfCalls} times, average ${sumTime / numberOfCalls}ms`; - if (metadata !== undefined) { - log.debug(message, metadata); - } else { - log.debug(message); - } + const message = `Routine ${methodName}: executed ${numberOfCalls} times, average ${sumTime / numberOfCalls}ms`; + log.debug(message); delete store.store[methodName]; } }); From e4ab86ade5541e5a91b5191ecbd649df6a737574 Mon Sep 17 00:00:00 2001 From: ejMina226 <118474890+ejMina226@users.noreply.github.com> Date: Fri, 7 Mar 2025 16:25:45 +0000 Subject: [PATCH 5/7] Add comments for clarity. --- packages/sequencer/src/logging/ConsoleTracer.ts | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/packages/sequencer/src/logging/ConsoleTracer.ts b/packages/sequencer/src/logging/ConsoleTracer.ts index 623d76f07..790c44394 100644 --- a/packages/sequencer/src/logging/ConsoleTracer.ts +++ b/packages/sequencer/src/logging/ConsoleTracer.ts @@ -23,6 +23,10 @@ export class ConsoleTracer implements Tracer { const store = container.resolve(TraceRecordHolder); const methodsAlreadyLogged = Object.keys(store.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. methodsAlreadyLogged.forEach((methodName) => { if ( Date.now() - store.store[methodName][0].startTime > From d02e2147abbd00ebeeda8ad929348f225c000bc3 Mon Sep 17 00:00:00 2001 From: Raphael Panic Date: Mon, 14 Apr 2025 14:50:00 +0200 Subject: [PATCH 6/7] Added possibility to manually trigger summary printing, added ascii table summary --- package-lock.json | 20 ++++ packages/sequencer/package.json | 5 +- .../sequencer/src/logging/ConsoleTracer.ts | 109 +++++++++++++----- .../test-integration/benchmarks/tps.test.ts | 10 +- 4 files changed, 110 insertions(+), 34 deletions(-) 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/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/logging/ConsoleTracer.ts b/packages/sequencer/src/logging/ConsoleTracer.ts index 790c44394..990177d3c 100644 --- a/packages/sequencer/src/logging/ConsoleTracer.ts +++ b/packages/sequencer/src/logging/ConsoleTracer.ts @@ -1,55 +1,104 @@ -import { injectable, singleton, container } from "tsyringe"; +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 { Tracer } from "./Tracer"; +import { closeable } from "../sequencer/builder/Closeable"; -type StoreType = Record; +import { Tracer } from "./Tracer"; -@singleton() -export class TraceRecordHolder { - public store: StoreType = {}; -} +type StoreType = Record; @injectable() +@closeable() export class ConsoleTracer implements Tracer { // Hard-code this for the moment. Needs to be configured. timeInterval: number = 8000; - public async trace( - name: string, - f: () => Promise, - metadata?: Record - ): Promise { - const store = container.resolve(TraceRecordHolder); - const methodsAlreadyLogged = Object.keys(store.store); + 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. - methodsAlreadyLogged.forEach((methodName) => { - if ( - Date.now() - store.store[methodName][0].startTime > - this.timeInterval - ) { - const sumTime = store.store[methodName].reduce((result, curr) => { - return result + curr.duration; - }, 0); - const numberOfCalls = store.store[methodName].length; - const message = `Routine ${methodName}: executed ${numberOfCalls} times, average ${sumTime / numberOfCalls}ms`; - log.debug(message); - delete store.store[methodName]; - } + 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 { + if (this.intervalId === undefined && this.type === "interval") { + this.intervalId = setInterval( + () => this.printSummary(), + this.timeInterval + ); + } + const startTime = Date.now(); const result = await f(); const duration = Date.now() - startTime; - if (name in store.store) { - store.store[name].push({ startTime, duration }); + + if (name in this.store) { + this.store[name].push({ duration }); } else { - store.store[name] = [{ startTime, duration }]; + 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/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); From b95e7cb301da746a97faf01494b5471e63ef9e7e Mon Sep 17 00:00:00 2001 From: Raphael Panic Date: Wed, 16 Apr 2025 13:41:49 +0200 Subject: [PATCH 7/7] Moved Tracer dependency to sequencer to be closeable --- packages/sdk/src/appChain/AppChain.ts | 2 -- packages/sequencer/src/index.ts | 2 +- ...soleLoggingFactory.ts => ConsoleTracingFactory.ts} | 2 +- .../sequencer/src/sequencer/executor/Sequencer.ts | 11 +++++++++-- 4 files changed, 11 insertions(+), 6 deletions(-) rename packages/sequencer/src/logging/{ConsoleLoggingFactory.ts => ConsoleTracingFactory.ts} (87%) 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/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/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