From 886ea9df1c22219880704340d451c593ebc9ef0f Mon Sep 17 00:00:00 2001 From: Alex Jbanca Date: Mon, 24 Jun 2024 18:36:13 +0300 Subject: [PATCH] benchmarking: Adding nim benchmark and qml wallet benchmark --- src/app/core/signals/signals_manager.nim | 10 ++++++- src/backend/core.nim | 8 ++++- src/dev/benchmark.nim | 29 +++++++++++++++---- src/nim_status_client.nim | 1 + ui/app/mainui/AppMain.qml | 5 +++- .../lib/include/DOtherSide/DOtherSide.h | 2 ++ vendor/DOtherSide/lib/src/DOtherSide.cpp | 15 +++++++++- vendor/nimqml | 2 +- vendor/status-go | 2 +- 9 files changed, 62 insertions(+), 12 deletions(-) diff --git a/src/app/core/signals/signals_manager.nim b/src/app/core/signals/signals_manager.nim index f0b0d0b5c8..b898c7249d 100644 --- a/src/app/core/signals/signals_manager.nim +++ b/src/app/core/signals/signals_manager.nim @@ -1,5 +1,6 @@ -import NimQml, json, strutils, chronicles, json_serialization +import NimQml, json, strutils, chronicles, json_serialization, strutils import ../eventemitter +import dev/benchmark as benchmark include types @@ -65,6 +66,13 @@ QtObject: proc receiveChroniclesLogEvent(self: SignalsManager, signal: string) {.slot.} = self.processSignal(signal, allowLogging=false) + proc logEvent(self: SignalsManager, logStr: string) {.slot.} = + if "benchmark start" in logStr: + benchmark.markCallsOfInterest = true + if "benchmark end" in logStr: + benchmark.markCallsOfInterest = false + info "QML logEvent", data = logStr + proc decode(self: SignalsManager, jsonSignal: JsonNode): Signal = let signalString = jsonSignal{"type"}.getStr var signalType: SignalType diff --git a/src/backend/core.nim b/src/backend/core.nim index 256f4244fb..fb04493d9c 100644 --- a/src/backend/core.nim +++ b/src/backend/core.nim @@ -1,6 +1,8 @@ import json, json_serialization, stew/shims/strformat, chronicles import status_go import response_type +import dev/benchmark +import std/times export response_type @@ -25,6 +27,10 @@ proc makePrivateRpcCall*( raise newException(RpcException, "db closed due to profile migration") try: debug "NewBE_callPrivateRPC", rpc_method=methodName + + let cpuTime = cpuTime() + defer: registerDuration(methodName, cpuTime, cpuTime()) + let rpcResponseRaw = status_go.callPrivateRPC($inputJSON) result = Json.decode(rpcResponseRaw, RpcResponse[JsonNode]) if(not result.error.isNil): @@ -77,7 +83,7 @@ proc callPrivateRPC*( proc callPrivateRPCNoDecode*( methodName: string, payload = %* [] -): string {.raises: [RpcException].} = +): string {.raises: [RpcException, Exception].} = let inputJSON = %* { "jsonrpc": "2.0", "method": methodName, diff --git a/src/dev/benchmark.nim b/src/dev/benchmark.nim index 13d0a9ec6a..1b1c2975ef 100644 --- a/src/dev/benchmark.nim +++ b/src/dev/benchmark.nim @@ -1,4 +1,4 @@ -import times, macros, strutils, locks, algorithm +import times, macros, strutils, locks, algorithm, std/exitprocs, std/locks # benchmark measure execution time of block of code. # usage: # import os, strutils, times @@ -45,6 +45,8 @@ type numRuns*: int totalTime*: float procName*: cstring + numRunsOnMainThread*: int + callOfInterest*: bool ProcBenchmarkPtr* = ptr ProcBenchmark @@ -53,11 +55,13 @@ type len*: int maxLen*: int - BenchmarkResult = tuple[procName: string, numRuns: int, totalTime: float, weight: float] + BenchmarkResult = tuple[procName: string, numRuns: int, totalTime: float, weight: float, numRunsOnMainThread: int, callOfInterest: bool] var lock: Lock benchmarkResults: ptr SharedProcBenchmarkArr + threadId: int + markCallsOfInterest*: bool = false # Forward declarations proc registerDuration*(name: string, startTime: float, endTime: float) {.gcsafe.} @@ -70,7 +74,8 @@ proc writeToFile(resultsToWrite: seq[BenchmarkResult]) proc resultCmp(x, y: BenchmarkResult): int # End of forward declarations -addQuitProc(quitCallback) +exitprocs.addExitProc(quitCallback) +threadId = getThreadId() macro benchmarkProc*(procDef: untyped): untyped = procDef.expectKind(nnkProcDef) @@ -96,6 +101,9 @@ proc registerDuration*(name: string, startTime: float, endTime: float) {.gcsafe. if benchmarkResults.data[i].procName == name.cstring: benchmarkResults.data[i].numRuns += 1 benchmarkResults.data[i].totalTime += endTime - startTime + if getThreadId() == threadId: + benchmarkResults.data[i].numRunsOnMainThread += 1 + benchmarkResults.data[i].callOfInterest = markCallsOfInterest or benchmarkResults.data[i].callOfInterest found = true if found: break @@ -113,6 +121,13 @@ proc registerDuration*(name: string, startTime: float, endTime: float) {.gcsafe. newProcBenchmark.procName = namePtr newProcBenchmark.numRuns = 1 newProcBenchmark.totalTime = endTime - startTime + if getThreadId() == threadId: + newProcBenchmark.numRunsOnMainThread = 1 + else: + newProcBenchmark.numRunsOnMainThread = 0 + + newProcBenchmark.callOfInterest = markCallsOfInterest + benchmarkResults.data[benchmarkResults.len] = newProcBenchmark benchmarkResults.len += 1 @@ -156,7 +171,7 @@ proc aggregateData(): seq[BenchmarkResult] = withLock lock: for i in 0 ..< benchmarkResults.len: totalWeight += benchmarkResults.data[i].totalTime - result.add(($(benchmarkResults.data[i].procName), benchmarkResults.data[i].numRuns, benchmarkResults.data[i].totalTime, 0.0)) + result.add(($(benchmarkResults.data[i].procName), benchmarkResults.data[i].numRuns, benchmarkResults.data[i].totalTime, 0.0, benchmarkResults.data[i].numRunsOnMainThread, benchmarkResults.data[i].callOfInterest)) result.sort(resultCmp) for i in 0 ..< result.len: @@ -171,13 +186,15 @@ proc writeToFile(resultsToWrite: seq[BenchmarkResult]) = except: echo "Could not open file procBenchmark.txt for writing" return - file.writeLine("Procedure, Number of runs, Total time in ms, Avg time in ms, Weight") + file.writeLine("Procedure, Number of runs, Total time in ms, Avg time in ms, Weight, Number of runs on main thread, Call of interest") for entry in resultsToWrite: file.writeLine(entry.procName & "," & $entry.numRuns & "," & $(entry.totalTime * 1000) & "," & $((entry.totalTime / entry.numRuns.float) * 1000) & - "," & $(entry.weight * 100) & "%") + "," & $(entry.weight * 100) & "%" & + "," & $(entry.numRunsOnMainThread) & + "," & $(entry.callOfInterest)) file.close() proc resultCmp(x, y: BenchmarkResult): int = diff --git a/src/nim_status_client.nim b/src/nim_status_client.nim index 338f695bc7..66235f1b27 100644 --- a/src/nim_status_client.nim +++ b/src/nim_status_client.nim @@ -202,6 +202,7 @@ proc mainProc() = signalsManagerQObjPointer = cast[pointer](statusFoundation.signalsManager.vptr) keycardServiceQObjPointer = cast[pointer](appController.keycardService.vptr) setupRemoteSignalsHandling() + registerLogHandler(signalsManagerQObjPointer) info fmt("Version: {APP_VERSION}") info fmt("Commit: {GIT_COMMIT}") diff --git a/ui/app/mainui/AppMain.qml b/ui/app/mainui/AppMain.qml index 4a1fb2fd9f..23d0a10a2a 100644 --- a/ui/app/mainui/AppMain.qml +++ b/ui/app/mainui/AppMain.qml @@ -1152,8 +1152,10 @@ Item { } if (activeSectionType === Constants.appSection.communitiesPortal) return Constants.appViewStackIndex.communitiesPortal - if (activeSectionType === Constants.appSection.wallet) + if (activeSectionType === Constants.appSection.wallet) { + print ("benchmark start") return Constants.appViewStackIndex.wallet + } if (activeSectionType === Constants.appSection.browser) return Constants.appViewStackIndex.browser if (activeSectionType === Constants.appSection.profile) @@ -1287,6 +1289,7 @@ Item { sendModalPopup: sendModal networkConnectionStore: appMain.networkConnectionStore appMainVisible: appMain.visible + Component.onCompleted: print ("benchmark end") } onLoaded: { item.resetView() diff --git a/vendor/DOtherSide/lib/include/DOtherSide/DOtherSide.h b/vendor/DOtherSide/lib/include/DOtherSide/DOtherSide.h index 14849bb41a..2f673b0367 100644 --- a/vendor/DOtherSide/lib/include/DOtherSide/DOtherSide.h +++ b/vendor/DOtherSide/lib/include/DOtherSide/DOtherSide.h @@ -104,6 +104,8 @@ DOS_API void DOS_CALL dos_qguiapplication_exec(void); /// \note This method was created because status-go has a non-QT event loop DOS_API void DOS_CALL dos_signal(DosQObject *vptr, const char *signal, const char *slot); +DOS_API void DOS_CALL dos_register_log_handler(DosQObject *vptr); + DOS_API DosQNetworkConfigurationManager *DOS_CALL dos_qncm_create(); DOS_API char * DOS_CALL dos_plain_text(char* htmlString); diff --git a/vendor/DOtherSide/lib/src/DOtherSide.cpp b/vendor/DOtherSide/lib/src/DOtherSide.cpp index 4f9518b95d..dfd6d639cd 100644 --- a/vendor/DOtherSide/lib/src/DOtherSide.cpp +++ b/vendor/DOtherSide/lib/src/DOtherSide.cpp @@ -114,6 +114,7 @@ class QMLNetworkAccessFactory : public QQmlNetworkAccessManagerFactory }; QString QMLNetworkAccessFactory::tmpPath = ""; +QObject* log_handler = nullptr; QNetworkAccessManager* QMLNetworkAccessFactory::create(QObject* parent) { @@ -211,9 +212,13 @@ void myMessageOutput(QtMsgType type, const QMessageLogContext &context, const QS fprintf(stderr, "Fatal: %s (%s:%u, %s)\n", localMsg.constData(), file, context.line, function); break; default: - fprintf(stderr, "Default: %s (%s:%u, %s)\n", localMsg.constData(), file, context.line, function); + fprintf(stderr, "!Default: %s (%s:%u, %s)\n", localMsg.constData(), file, context.line, function); break; } + + if (log_handler != nullptr) { + QMetaObject::invokeMethod(log_handler, "logEvent", Qt::QueuedConnection, Q_ARG(QString, QStringLiteral("%1 (%2:%3, %4)").arg(localMsg.constData()).arg(file).arg(context.line).arg(function))); + } } void dos_qguiapplication_create() @@ -1101,6 +1106,14 @@ void dos_signal(::DosQObject *vptr, const char *signal, const char *slot) // QMetaObject::invokeMethod(qobject, slot_copy.c_str(), Qt::QueuedConnection, Q_ARG(QString, signal_copy.c_str())); } +void dos_register_log_handler(::DosQObject *vptr) +{ + log_handler = static_cast(vptr); + QObject::connect(log_handler, &QObject::destroyed, []() { + log_handler = nullptr; + }); +} + void dos_qmetaobject_delete(::DosQMetaObject *vptr) { auto factory = static_cast(vptr); diff --git a/vendor/nimqml b/vendor/nimqml index 20d4db12bb..3040c233fc 160000 --- a/vendor/nimqml +++ b/vendor/nimqml @@ -1 +1 @@ -Subproject commit 20d4db12bb40dcf1c549ab3149ca0b4b791e90b7 +Subproject commit 3040c233fc9ad2c7affe584e3fcc735aa6fae190 diff --git a/vendor/status-go b/vendor/status-go index 891300a758..3c99701812 160000 --- a/vendor/status-go +++ b/vendor/status-go @@ -1 +1 @@ -Subproject commit 891300a758c7ed19d2d53428afba0dd2d79ad251 +Subproject commit 3c99701812ebaac5b0749a7960869bd01ba9c3ef