benchmarking: Adding nim benchmark and qml wallet benchmark

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

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,

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 =

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}")

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()

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);

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<QObject *>(vptr);
+   QObject::connect(log_handler, &QObject::destroyed, []() {
+       log_handler = nullptr;
+   });
+}
+
 void dos_qmetaobject_delete(::DosQMetaObject *vptr)
 {
     auto factory = static_cast<DOS::DosIQMetaObjectHolder *>(vptr);

vendor/nimqml

@@ -1 +1 @@
-Subproject commit 20d4db12bb40dcf1c549ab3149ca0b4b791e90b7
+Subproject commit 3040c233fc9ad2c7affe584e3fcc735aa6fae190

vendor/status-go

@@ -1 +1 @@
-Subproject commit 891300a758c7ed19d2d53428afba0dd2d79ad251
+Subproject commit 3c99701812ebaac5b0749a7960869bd01ba9c3ef