From f10c3f393463f6a0686929781ecf9f7142b55644 Mon Sep 17 00:00:00 2001 From: Ben Bierens <39762930+benbierens@users.noreply.github.com> Date: Tue, 22 Aug 2023 08:35:16 +0200 Subject: [PATCH] Debug/extra logging (#509) * logs * poll log * more logs * time log for upload steps * Adds metric and log for block retrieval time * adds some logging * move logging for storestream block indices * Log at start and end of block iteration * applies branch blockstore-bugfix * Cleanup * Cleanup --- codex/blockexchange/engine/discovery.nim | 6 ++++-- codex/blockexchange/engine/pendingblocks.nim | 12 +++++++++++- codex/node.nim | 3 ++- codex/rest/api.nim | 4 +++- codex/streams/storestream.nim | 4 ++-- 5 files changed, 22 insertions(+), 7 deletions(-) diff --git a/codex/blockexchange/engine/discovery.nim b/codex/blockexchange/engine/discovery.nim index d93b4cfb..8a7fd1a9 100644 --- a/codex/blockexchange/engine/discovery.nim +++ b/codex/blockexchange/engine/discovery.nim @@ -78,13 +78,15 @@ proc discoveryQueueLoop(b: DiscoveryEngine) {.async.} = trace "About to sleep discovery loop" await sleepAsync(b.discoveryLoopSleep) -proc advertiseQueueLoop*(b: DiscoveryEngine) {.async.} = +proc advertiseQueueLoop(b: DiscoveryEngine) {.async.} = while b.discEngineRunning: if cids =? await b.localStore.listBlocks(blockType = b.advertiseType): + trace "Begin iterating blocks..." for c in cids: if cid =? await c: await b.advertiseQueue.put(cid) await sleepAsync(50.millis) + trace "Iterating blocks finished." trace "About to sleep advertise loop", sleep = b.advertiseLoopSleep await sleepAsync(b.advertiseLoopSleep) @@ -256,7 +258,7 @@ proc new*( advertiseType = BlockType.Both ): DiscoveryEngine = ## Create a discovery engine instance for advertising services - ## + ## DiscoveryEngine( localStore: localStore, peers: peers, diff --git a/codex/blockexchange/engine/pendingblocks.nim b/codex/blockexchange/engine/pendingblocks.nim index e897a66f..98ce77fe 100644 --- a/codex/blockexchange/engine/pendingblocks.nim +++ b/codex/blockexchange/engine/pendingblocks.nim @@ -8,6 +8,7 @@ ## those terms. import std/tables +import std/monotimes import pkg/upraises @@ -24,6 +25,7 @@ logScope: topics = "codex pendingblocks" declareGauge(codexBlockExchangePendingBlockRequests, "codex blockexchange pending block requests") +declareGauge(codexBlockExchangeRetrievalTimeUs, "codex blockexchange block retrieval time us") const DefaultBlockTimeout* = 10.minutes @@ -32,6 +34,7 @@ type BlockReq* = object handle*: Future[Block] inFlight*: bool + startTime*: int64 PendingBlocksManager* = ref object of RootObj blocks*: Table[Cid, BlockReq] # pending Block requests @@ -52,7 +55,8 @@ proc getWantHandle*( if cid notin p.blocks: p.blocks[cid] = BlockReq( handle: newFuture[Block]("pendingBlocks.getWantHandle"), - inFlight: inFlight) + inFlight: inFlight, + startTime: getMonoTime().ticks) trace "Adding pending future for block", cid, inFlight = p.blocks[cid].inFlight @@ -80,6 +84,12 @@ proc resolve*(p: PendingBlocksManager, if not pending[].handle.completed: trace "Resolving block", cid = blk.cid pending[].handle.complete(blk) + let + startTime = pending[].startTime + stopTime = getMonoTime().ticks + retrievalDurationUs = (stopTime - startTime) div 1000 + codexBlockExchangeRetrievalTimeUs.set(retrievalDurationUs) + trace "Block retrieval time", retrievalDurationUs proc setInFlight*(p: PendingBlocksManager, cid: Cid, diff --git a/codex/node.nim b/codex/node.nim index d95ad078..ac7b44a5 100644 --- a/codex/node.nim +++ b/codex/node.nim @@ -227,7 +227,8 @@ proc store*( trace "Stored data", manifestCid = manifest.cid, contentCid = cid, - blocks = blockManifest.len + blocks = blockManifest.len, + size=blockManifest.originalBytes # Announce manifest await self.discovery.provide(manifest.cid) diff --git a/codex/rest/api.nim b/codex/rest/api.nim index db4e0d9c..0a5728fa 100644 --- a/codex/rest/api.nim +++ b/codex/rest/api.nim @@ -247,13 +247,15 @@ proc initRestApi*(node: CodexNodeRef, conf: CodexConf): RestRouter = trace "Uploaded file", cid return RestApiResponse.response($cid) except CancelledError: + trace "Upload cancelled error" return RestApiResponse.error(Http500) except AsyncStreamError: + trace "Async stream error" return RestApiResponse.error(Http500) finally: await reader.closeWait() - # if we got here something went wrong? + trace "Something went wrong error" return RestApiResponse.error(Http500) router.api( diff --git a/codex/streams/storestream.nim b/codex/streams/storestream.nim index 809d961c..94dcc2d3 100644 --- a/codex/streams/storestream.nim +++ b/codex/streams/storestream.nim @@ -52,7 +52,7 @@ proc new*( pad = true ): StoreStream = ## Create a new StoreStream instance for a given store and manifest - ## + ## result = StoreStream( store: store, manifest: manifest, @@ -79,7 +79,7 @@ method readOnce*( ## Read `nbytes` from current position in the StoreStream into output buffer pointed by `pbytes`. ## Return how many bytes were actually read before EOF was encountered. ## Raise exception if we are already at EOF. - ## + ## trace "Reading from manifest", cid = self.manifest.cid.get(), blocks = self.manifest.len if self.atEof: