From 3631de7fe38a2896bc59a0c191ffcec44d49aa20 Mon Sep 17 00:00:00 2001 From: Ivan Folgueira Bande Date: Sun, 6 Oct 2024 16:50:37 +0200 Subject: [PATCH 1/3] simple change better waku store debug logs with some timing info --- waku/waku_store/protocol.nim | 8 ++++-- waku/waku_store_legacy/protocol.nim | 42 +++++++++++++++++++---------- 2 files changed, 34 insertions(+), 16 deletions(-) diff --git a/waku/waku_store/protocol.nim b/waku/waku_store/protocol.nim index 5a8a81c132..5f986983eb 100644 --- a/waku/waku_store/protocol.nim +++ b/waku/waku_store/protocol.nim @@ -91,6 +91,7 @@ proc initProtocolHandler(self: WakuStore) = proc handler(conn: Connection, proto: string) {.async, gcsafe, closure.} = var successfulQuery = false ## only consider the correct queries in metrics var resBuf: StoreResp + var queryDuration: float self.requestRateLimiter.checkUsageLimit(WakuStoreCodec, conn): let readRes = catch: await conn.readLp(DefaultMaxRpcSize.int) @@ -107,7 +108,7 @@ proc initProtocolHandler(self: WakuStore) = resBuf = await self.handleQueryRequest(conn.peerId, reqBuf) - let queryDuration = getTime().toUnixFloat() - queryStartTime + queryDuration = getTime().toUnixFloat() - queryStartTime waku_store_time_seconds.set(queryDuration, ["query-db-time"]) successfulQuery = true do: @@ -124,10 +125,13 @@ proc initProtocolHandler(self: WakuStore) = error "Connection write error", error = writeRes.error.msg return - debug "after sending response", requestId = resBuf.requestId if successfulQuery: let writeDuration = getTime().toUnixFloat() - writeRespStartTime waku_store_time_seconds.set(writeDuration, ["send-store-resp-time"]) + debug "after sending response", + requestId = resBuf.requestId, + queryDurationSecs = queryDuration, + writeStreamDurationSecs = writeDuration waku_service_network_bytes.inc( amount = resBuf.resp.len().int64, labelValues = [WakuStoreCodec, "out"] diff --git a/waku/waku_store_legacy/protocol.nim b/waku/waku_store_legacy/protocol.nim index 4e06419b49..d72308e63b 100644 --- a/waku/waku_store_legacy/protocol.nim +++ b/waku/waku_store_legacy/protocol.nim @@ -37,23 +37,23 @@ type WakuStore* = ref object of LPProtocol ## Protocol +type StoreResp = tuple[resp: seq[byte], requestId: string] + proc handleLegacyQueryRequest( self: WakuStore, requestor: PeerId, raw_request: seq[byte] -): Future[seq[byte]] {.async.} = +): Future[StoreResp] {.async.} = let decodeRes = HistoryRPC.decode(raw_request) if decodeRes.isErr(): - error "failed to decode rpc", peerId = requestor + error "failed to decode rpc", peerId = requestor, error = $decodeRes.error waku_legacy_store_errors.inc(labelValues = [decodeRpcFailure]) - # TODO: Return (BAD_REQUEST, cause: "decode rpc failed") - return + return (newSeq[byte](), "failed to decode rpc") let reqRpc = decodeRes.value if reqRpc.query.isNone(): error "empty query rpc", peerId = requestor, requestId = reqRpc.requestId waku_legacy_store_errors.inc(labelValues = [emptyRpcQueryFailure]) - # TODO: Return (BAD_REQUEST, cause: "empty query") - return + return (newSeq[byte](), "empty query rpc") let requestId = reqRpc.requestId var request = reqRpc.query.get().toAPI() @@ -72,21 +72,30 @@ proc handleLegacyQueryRequest( let error = HistoryError(kind: HistoryErrorKind.UNKNOWN).toRPC() let response = HistoryResponseRPC(error: error) - return HistoryRPC(requestId: requestId, response: some(response)).encode().buffer + return ( + HistoryRPC(requestId: requestId, response: some(response)).encode().buffer, + requestId, + ) if responseRes.isErr(): error "history query failed", peerId = requestor, requestId = requestId, error = responseRes.error let response = responseRes.toRPC() - return HistoryRPC(requestId: requestId, response: some(response)).encode().buffer + return ( + HistoryRPC(requestId: requestId, response: some(response)).encode().buffer, + requestId, + ) let response = responseRes.toRPC() info "sending history response", peerId = requestor, requestId = requestId, messages = response.messages.len - return HistoryRPC(requestId: requestId, response: some(response)).encode().buffer + return ( + HistoryRPC(requestId: requestId, response: some(response)).encode().buffer, + requestId, + ) proc initProtocolHandler(ws: WakuStore) = let rejectResponseBuf = HistoryRPC( @@ -103,7 +112,8 @@ proc initProtocolHandler(ws: WakuStore) = proc handler(conn: Connection, proto: string) {.async, closure.} = var successfulQuery = false ## only consider the correct queries in metrics - var resBuf: seq[byte] + var resBuf: StoreResp + var queryDuration: float ws.requestRateLimiter.checkUsageLimit(WakuLegacyStoreCodec, conn): let readRes = catch: await conn.readLp(DefaultMaxRpcSize.int) @@ -118,17 +128,17 @@ proc initProtocolHandler(ws: WakuStore) = let queryStartTime = getTime().toUnixFloat() resBuf = await ws.handleLegacyQueryRequest(conn.peerId, reqBuf) - let queryDuration = getTime().toUnixFloat() - queryStartTime + 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 + resBuf = (rejectResponseBuf, "rejected") let writeRespStartTime = getTime().toUnixFloat() let writeRes = catch: - await conn.writeLp(resBuf) + await conn.writeLp(resBuf.resp) if writeRes.isErr(): error "Connection write error", error = writeRes.error.msg @@ -137,9 +147,13 @@ proc initProtocolHandler(ws: WakuStore) = if successfulQuery: let writeDuration = getTime().toUnixFloat() - writeRespStartTime waku_legacy_store_time_seconds.set(writeDuration, ["send-store-resp-time"]) + debug "after sending response", + requestId = resBuf.requestId, + queryDurationSecs = queryDuration, + writeStreamDurationSecs = writeDuration waku_service_network_bytes.inc( - amount = resBuf.len().int64, labelValues = [WakuLegacyStoreCodec, "out"] + amount = resBuf.resp.len().int64, labelValues = [WakuLegacyStoreCodec, "out"] ) ws.handler = handler From 54cc764ee048c7a107cc6c378c0aa9fd1a7199e6 Mon Sep 17 00:00:00 2001 From: Ivan Folgueira Bande Date: Sun, 6 Oct 2024 17:35:09 +0200 Subject: [PATCH 2/3] dbconn: give some more name clarity --- waku/common/databases/db_postgres/dbconn.nim | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/waku/common/databases/db_postgres/dbconn.nim b/waku/common/databases/db_postgres/dbconn.nim index aae8d80bc6..0f6437494f 100644 --- a/waku/common/databases/db_postgres/dbconn.nim +++ b/waku/common/databases/db_postgres/dbconn.nim @@ -230,7 +230,7 @@ proc dbConnQuery*( return err("error in dbConnQuery calling sendQuery: " & $error) let sendDuration = getTime().toUnixFloat() - queryStartTime - query_time_secs.set(sendDuration, [querySummary, "sendQuery"]) + query_time_secs.set(sendDuration, [querySummary, "sendToDBQuery"]) queryStartTime = getTime().toUnixFloat() @@ -247,8 +247,8 @@ proc dbConnQuery*( requestId, query = $query, querySummary, - waitDurationSecs = waitDuration, - sendDurationSecs = sendDuration + waitDbQueryDurationSecs = waitDuration, + sendToDBDurationSecs = sendDuration return ok() @@ -270,7 +270,7 @@ proc dbConnQueryPrepared*( return err("error in dbConnQueryPrepared calling sendQuery: " & $error) let sendDuration = getTime().toUnixFloat() - queryStartTime - query_time_secs.set(sendDuration, [stmtName, "sendQuery"]) + query_time_secs.set(sendDuration, [stmtName, "sendToDBQuery"]) queryStartTime = getTime().toUnixFloat() From 4397792233687461864aa643e9ee0060d13343ff Mon Sep 17 00:00:00 2001 From: Ivan Folgueira Bande Date: Sun, 6 Oct 2024 20:31:20 +0200 Subject: [PATCH 3/3] dbconn: some more log detail --- waku/common/databases/db_postgres/dbconn.nim | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/waku/common/databases/db_postgres/dbconn.nim b/waku/common/databases/db_postgres/dbconn.nim index 0f6437494f..6ed26d9289 100644 --- a/waku/common/databases/db_postgres/dbconn.nim +++ b/waku/common/databases/db_postgres/dbconn.nim @@ -246,6 +246,7 @@ proc dbConnQuery*( debug "dbConnQuery", requestId, query = $query, + args, querySummary, waitDbQueryDurationSecs = waitDuration, sendToDBDurationSecs = sendDuration @@ -286,7 +287,8 @@ proc dbConnQueryPrepared*( debug "dbConnQueryPrepared", requestId, stmtName, - waitDurationSecs = waitDuration, - sendDurationSecs = sendDuration + paramValues, + waitDbQueryDurationSecs = waitDuration, + sendToDBDurationSecs = sendDuration return ok()