chore: extending store metrics (#3042)

* adding query_metrics module
* update fleet-dashboard with new store panels for better timing insight

library/callback.nim

@@ -4,7 +4,9 @@ type WakuCallBack* = proc(
   callerRet: cint, msg: ptr cchar, len: csize_t, userData: pointer
 ) {.cdecl, gcsafe, raises: [].}
 
-template checkLibwakuParams*(ctx: ptr WakuContext, callback: WakuCallBack, userData: pointer) =
+template checkLibwakuParams*(
+    ctx: ptr WakuContext, callback: WakuCallBack, userData: pointer
+) =
   ctx[].userData = userData
 
   if isNil(callback):

library/libwaku.nim

@@ -487,9 +487,7 @@ proc waku_get_peerids_from_peerstore(
   let connRes = waku_thread.sendRequestToWakuThread(
     ctx,
     RequestType.PEER_MANAGER,
-    PeerManagementRequest.createShared(
-      PeerManagementMsgType.GET_ALL_PEER_IDS
-    ),
+    PeerManagementRequest.createShared(PeerManagementMsgType.GET_ALL_PEER_IDS),
   )
   if connRes.isErr():
     let msg = $connRes.error

waku/common/databases/db_postgres/dbconn.nim

@@ -1,4 +1,5 @@
-import std/[times, strutils, asyncnet, os, sequtils], results, chronos
+import std/[times, strutils, asyncnet, os, sequtils], results, chronos, metrics, re
+import ./query_metrics
 
 include db_connector/db_postgres
 
@@ -45,6 +46,9 @@ proc closeDbConn*(db: DbConn) {.raises: [OSError].} =
     asyncengine.unregister(cast[asyncengine.AsyncFD](fd))
   db.close()
 
+proc `$`(self: SqlQuery): string =
+  return cast[string](self)
+
 proc sendQuery(
     db: DbConn, query: SqlQuery, args: seq[string]
 ): Future[Result[void, string]] {.async.} =
@@ -152,12 +156,32 @@ proc waitQueryToFinish(
 proc dbConnQuery*(
     db: DbConn, query: SqlQuery, args: seq[string], rowCallback: DataProc
 ): Future[Result[void, string]] {.async, gcsafe.} =
+  let cleanedQuery = ($query).replace(" ", "").replace("\n", "")
+  ## remove everything between ' or " all possible sequence of numbers. e.g. rm partition partition
+  var querySummary = cleanedQuery.replace(re"""(['"]).*?\1""", "")
+  querySummary = querySummary.replace(re"\d+", "")
+  querySummary = "query_tag_" & querySummary[0 ..< min(querySummary.len, 200)]
+
+  var queryStartTime = getTime().toUnixFloat()
+
   (await db.sendQuery(query, args)).isOkOr:
     return err("error in dbConnQuery calling sendQuery: " & $error)
 
+  query_time_secs.set(
+    getTime().toUnixFloat() - queryStartTime, [querySummary, "sendQuery"]
+  )
+
+  queryStartTime = getTime().toUnixFloat()
+
   (await db.waitQueryToFinish(rowCallback)).isOkOr:
     return err("error in dbConnQuery calling waitQueryToFinish: " & $error)
 
+  query_time_secs.set(
+    getTime().toUnixFloat() - queryStartTime, [querySummary, "waitFinish"]
+  )
+
+  query_count.inc(labelValues = [querySummary])
+
   return ok()
 
 proc dbConnQueryPrepared*(
@@ -168,10 +192,21 @@ proc dbConnQueryPrepared*(
     paramFormats: seq[int32],
     rowCallback: DataProc,
 ): Future[Result[void, string]] {.async, gcsafe.} =
+  var queryStartTime = getTime().toUnixFloat()
   db.sendQueryPrepared(stmtName, paramValues, paramLengths, paramFormats).isOkOr:
     return err("error in dbConnQueryPrepared calling sendQuery: " & $error)
 
+  query_time_secs.set(getTime().toUnixFloat() - queryStartTime, [stmtName, "sendQuery"])
+
+  queryStartTime = getTime().toUnixFloat()
+
   (await db.waitQueryToFinish(rowCallback)).isOkOr:
     return err("error in dbConnQueryPrepared calling waitQueryToFinish: " & $error)
 
+  query_time_secs.set(
+    getTime().toUnixFloat() - queryStartTime, [stmtName, "waitFinish"]
+  )
+
+  query_count.inc(labelValues = [stmtName])
+
   return ok()

waku/common/databases/db_postgres/query_metrics.nim

@@ -0,0 +1,7 @@
+import metrics
+
+declarePublicGauge query_time_secs,
+  "query time measured in nanoseconds", labels = ["query", "phase"]
+
+declarePublicCounter query_count,
+  "number of times a query is being performed", labels = ["query"]

waku/waku_store/protocol.nim

@@ -108,7 +108,7 @@ proc initProtocolHandler(self: WakuStore) =
       resBuf = await self.handleQueryRequest(conn.peerId, reqBuf)
 
       let queryDuration = getTime().toUnixFloat() - queryStartTime
-      waku_store_time_seconds.inc(amount = queryDuration, labelValues = ["query-db"])
+      waku_store_time_seconds.set(queryDuration, ["query-db-time"])
       successfulQuery = true
     do:
       debug "store query request rejected due rate limit exceeded",
@@ -127,7 +127,7 @@ proc initProtocolHandler(self: WakuStore) =
     debug "after sending response", requestId = resBuf.requestId
     if successfulQuery:
       let writeDuration = getTime().toUnixFloat() - writeRespStartTime
-      waku_store_time_seconds.inc(amount = writeDuration, labelValues = ["send-resp"])
+      waku_store_time_seconds.set(writeDuration, ["send-store-resp-time"])
 
     waku_service_network_bytes.inc(
       amount = resBuf.resp.len().int64, labelValues = [WakuStoreCodec, "out"]

waku/waku_store/protocol_metrics.nim

@@ -5,8 +5,8 @@ import metrics
 declarePublicGauge waku_store_errors, "number of store protocol errors", ["type"]
 declarePublicGauge waku_store_queries, "number of store queries received"
 
-## f.e., we have the "query" phase, where the node performs the query to the database,
-## and the "libp2p" phase, where the node writes the store response to the libp2p stream.
+## "query-db-time" phase considers the time when node performs the query to the database.
+## "send-store-resp-time" phase is the time when node writes the store response to the store-client.
 declarePublicGauge waku_store_time_seconds,
   "Time in seconds spent by each store phase", labels = ["phase"]
 

waku/waku_store_legacy/protocol.nim

@@ -4,7 +4,7 @@
 {.push raises: [].}
 
 import
-  std/options,
+  std/[options, times],
   results,
   chronicles,
   chronos,
@@ -102,6 +102,7 @@ proc initProtocolHandler(ws: WakuStore) =
   ).encode().buffer
 
   proc handler(conn: Connection, proto: string) {.async, closure.} =
+    var successfulQuery = false ## only consider the correct queries in metrics
     var resBuf: seq[byte]
     ws.requestRateLimiter.checkUsageLimit(WakuLegacyStoreCodec, conn):
       let readRes = catch:
@@ -115,12 +116,17 @@ proc initProtocolHandler(ws: WakuStore) =
         amount = reqBuf.len().int64, labelValues = [WakuLegacyStoreCodec, "in"]
       )
 
+      let queryStartTime = getTime().toUnixFloat()
       resBuf = await ws.handleLegacyQueryRequest(conn.peerId, reqBuf)
+      let queryDuration = getTime().toUnixFloat() - queryStartTime
+      waku_legacy_store_time_seconds.set(queryDuration, ["query-db-time"])
+      successfulQuery = true
     do:
       debug "Legacy store query request rejected due rate limit exceeded",
         peerId = conn.peerId, limit = $ws.requestRateLimiter.setting
       resBuf = rejectResponseBuf
 
+    let writeRespStartTime = getTime().toUnixFloat()
     let writeRes = catch:
       await conn.writeLp(resBuf)
 
@@ -128,6 +134,10 @@ proc initProtocolHandler(ws: WakuStore) =
       error "Connection write error", error = writeRes.error.msg
       return
 
+    if successfulQuery:
+      let writeDuration = getTime().toUnixFloat() - writeRespStartTime
+      waku_legacy_store_time_seconds.set(writeDuration, ["send-store-resp-time"])
+
     waku_service_network_bytes.inc(
       amount = resBuf.len().int64, labelValues = [WakuLegacyStoreCodec, "out"]
     )

waku/waku_store_legacy/protocol_metrics.nim

@@ -6,6 +6,11 @@ declarePublicGauge waku_legacy_store_errors,
   "number of legacy store protocol errors", ["type"]
 declarePublicGauge waku_legacy_store_queries, "number of legacy store queries received"
 
+## "query-db-time" phase considers the time when node performs the query to the database.
+## "send-store-resp-time" phase is the time when node writes the store response to the store-client.
+declarePublicGauge waku_legacy_store_time_seconds,
+  "Time in seconds spent by each store phase", labels = ["phase"]
+
 # Error types (metric label values)
 const
   dialFailure* = "dial_failure"