From 35a93cc40db670429917f45c5b2e26e670280c9d Mon Sep 17 00:00:00 2001 From: thatben Date: Mon, 13 Jan 2025 15:59:11 +0100 Subject: [PATCH 1/7] Adds duration to repostore logs for getBlock and putBlock --- .github/workflows/docker-dist-tests.yml | 2 +- codex/stores/repostore/store.nim | 23 ++++++++++++++++++++++- 2 files changed, 23 insertions(+), 2 deletions(-) diff --git a/.github/workflows/docker-dist-tests.yml b/.github/workflows/docker-dist-tests.yml index 1cbc528a..22b23e52 100644 --- a/.github/workflows/docker-dist-tests.yml +++ b/.github/workflows/docker-dist-tests.yml @@ -30,7 +30,7 @@ jobs: name: Build and Push uses: ./.github/workflows/docker-reusable.yml with: - nimflags: '-d:disableMarchNative -d:codex_enable_api_debug_peers=true -d:codex_enable_proof_failures=true -d:codex_enable_log_counter=true -d:verify_circuit=true' + nimflags: '-d:disableMarchNative -d:codex_enable_api_debug_peers=true -d:codex_enable_proof_failures=true -d:codex_enable_log_counter=true -d:verify_circuit=true -d:codex_enable_repostore_timinglogs=true' nat_ip_auto: true tag_latest: ${{ github.ref_name == github.event.repository.default_branch || startsWith(github.ref, 'refs/tags/') }} tag_suffix: dist-tests diff --git a/codex/stores/repostore/store.nim b/codex/stores/repostore/store.nim index 63c59d2b..31841996 100644 --- a/codex/stores/repostore/store.nim +++ b/codex/stores/repostore/store.nim @@ -27,6 +27,12 @@ import ../../logutils import ../../merkletree import ../../utils +const + codex_enable_repostore_timinglogs* {.booldefine.} = false + +when codex_enable_repostore_timinglogs: + import std/monotimes + export blocktype, cid logScope: @@ -51,6 +57,9 @@ method getBlock*(self: RepoStore, cid: Cid): Future[?!Block] {.async.} = trace "Error getting key from provider", err = err.msg return failure(err) + when codex_enable_repostore_timinglogs: + let startTime = getMonoTime().ticks + without data =? await self.repoDs.get(key), err: if not (err of DatastoreKeyNotFound): trace "Error getting block from datastore", err = err.msg, key @@ -58,7 +67,12 @@ method getBlock*(self: RepoStore, cid: Cid): Future[?!Block] {.async.} = return failure(newException(BlockNotFoundError, err.msg)) - trace "Got block for cid", cid + when codex_enable_repostore_timinglogs: + let durationUs = (getMonoTime().ticks - startTime) div 1000 + trace "Got block for cid", cid, durationUs + else: + trace "Got block for cid", cid + return Block.new(cid, data, verify = true) method getBlockAndProof*(self: RepoStore, treeCid: Cid, index: Natural): Future[?!(Block, CodexProof)] {.async.} = @@ -176,6 +190,9 @@ method putBlock*( let expiry = self.clock.now() + (ttl |? self.blockTtl).seconds + when codex_enable_repostore_timinglogs: + let startTime = getMonoTime().ticks + without res =? await self.storeBlock(blk, expiry), err: return failure(err) @@ -195,6 +212,10 @@ method putBlock*( else: trace "Block already exists" + when codex_enable_repostore_timinglogs: + let durationUs = (getMonoTime().ticks - startTime) div 1000 + trace "putBlock", durationUs + return success() method delBlock*(self: RepoStore, cid: Cid): Future[?!void] {.async.} = From 64f92716a03de6df5f4dac59258f31aa24f02821 Mon Sep 17 00:00:00 2001 From: Ben Date: Tue, 14 Jan 2025 16:07:16 +0100 Subject: [PATCH 2/7] Sets up statistics summary metric collector --- codex/utils/statsummary.nim | 45 +++++++++++++++++++++++++++++++++++++ 1 file changed, 45 insertions(+) create mode 100644 codex/utils/statsummary.nim diff --git a/codex/utils/statsummary.nim b/codex/utils/statsummary.nim new file mode 100644 index 00000000..df4729bd --- /dev/null +++ b/codex/utils/statsummary.nim @@ -0,0 +1,45 @@ +import pkg/metrics + +when defined(metrics): + type StatSummary* = ref object of Collector + min: float64 + max: float64 + ravg: float64 + + method collect(st: StatSummary, output: MetricHandler) = + let timestamp = st.now() + output( + name = st.name & "_min", + value = st.min, + timestamp = timestamp + ) + output( + name = st.name & "_max", + value = st.max, + timestamp = timestamp + ) + output( + name = st.name & "_ravg", + value = st.ravg, + timestamp = timestamp + ) + +proc declareStatSummary*(name: string, help: string = ""): StatSummary = + when defined(metrics): + result = StatSummary.newCollector(name, help) + result.min = high(float64) + result.max = low(float64) + else: + return IgnoredCollector + +proc observeStatSummary(st: StatSummary, value: float64) = + if value < st.min: + st.min = value + if value > st.max: + st.max = value + st.ravg = (st.ravg + value) / 2.0 + +template observe*(statSummary: StatSummary | type IgnoredCollector, amount: int64 | float64 = 1) = + when defined(metrics) and statSummary is not IgnoredCollector: + {.gcsafe.}: + observeStatSummary(statSummary, amount.float64) From 92b6be0db118e042a243511ae15599389023d26a Mon Sep 17 00:00:00 2001 From: thatben Date: Wed, 15 Jan 2025 10:46:58 +0100 Subject: [PATCH 3/7] fixes initialization of stat values --- codex/utils/statsummary.nim | 19 ++++++++++++++----- 1 file changed, 14 insertions(+), 5 deletions(-) diff --git a/codex/utils/statsummary.nim b/codex/utils/statsummary.nim index df4729bd..ff9080e6 100644 --- a/codex/utils/statsummary.nim +++ b/codex/utils/statsummary.nim @@ -2,11 +2,15 @@ import pkg/metrics when defined(metrics): type StatSummary* = ref object of Collector + hasValues: bool min: float64 max: float64 ravg: float64 method collect(st: StatSummary, output: MetricHandler) = + if not st.hasValues: + return + let timestamp = st.now() output( name = st.name & "_min", @@ -27,17 +31,22 @@ when defined(metrics): proc declareStatSummary*(name: string, help: string = ""): StatSummary = when defined(metrics): result = StatSummary.newCollector(name, help) - result.min = high(float64) - result.max = low(float64) + result.hasValues = false else: return IgnoredCollector proc observeStatSummary(st: StatSummary, value: float64) = - if value < st.min: + if st.hasValues: + if value < st.min: + st.min = value + if value > st.max: + st.max = value + st.ravg = (st.ravg + value) / float64(2) + else: + st.hasValues = true st.min = value - if value > st.max: st.max = value - st.ravg = (st.ravg + value) / 2.0 + st.ravg = value template observe*(statSummary: StatSummary | type IgnoredCollector, amount: int64 | float64 = 1) = when defined(metrics) and statSummary is not IgnoredCollector: From a9e55e665ae6fd7cd3cca8c458fe3b02a0fa6a02 Mon Sep 17 00:00:00 2001 From: thatben Date: Wed, 15 Jan 2025 10:48:49 +0100 Subject: [PATCH 4/7] Applies statSummary metric in repostore. --- codex/stores/repostore/store.nim | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/codex/stores/repostore/store.nim b/codex/stores/repostore/store.nim index 31841996..b11970bd 100644 --- a/codex/stores/repostore/store.nim +++ b/codex/stores/repostore/store.nim @@ -32,6 +32,11 @@ const when codex_enable_repostore_timinglogs: import std/monotimes + import ../../utils/statsummary + + let + getBlockSummary = declareStatSummary("getBlock") + putBlockSummary = declareStatSummary("putBlock") export blocktype, cid @@ -70,6 +75,7 @@ method getBlock*(self: RepoStore, cid: Cid): Future[?!Block] {.async.} = when codex_enable_repostore_timinglogs: let durationUs = (getMonoTime().ticks - startTime) div 1000 trace "Got block for cid", cid, durationUs + getBlockSummary.observe(durationUs) else: trace "Got block for cid", cid @@ -215,6 +221,7 @@ method putBlock*( when codex_enable_repostore_timinglogs: let durationUs = (getMonoTime().ticks - startTime) div 1000 trace "putBlock", durationUs + putBlockSummary.observe(durationUs) return success() From fa78e7ce9c2341ceaa41ff8497616928c27f63ac Mon Sep 17 00:00:00 2001 From: Ben Bierens <39762930+benbierens@users.noreply.github.com> Date: Thu, 30 Jan 2025 17:09:23 +0100 Subject: [PATCH 5/7] Update codex/stores/repostore/store.nim Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Signed-off-by: Ben Bierens <39762930+benbierens@users.noreply.github.com> --- codex/stores/repostore/store.nim | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/codex/stores/repostore/store.nim b/codex/stores/repostore/store.nim index c32eb805..1137f3e4 100644 --- a/codex/stores/repostore/store.nim +++ b/codex/stores/repostore/store.nim @@ -27,8 +27,7 @@ import ../../logutils import ../../merkletree import ../../utils -const - codex_enable_repostore_timinglogs* {.booldefine.} = false +const codex_enable_repostore_timinglogs* {.booldefine.} = false when codex_enable_repostore_timinglogs: import std/monotimes From d70af86d2ad8ca05b2f5e4a3672e25b69d9b795d Mon Sep 17 00:00:00 2001 From: Ben Bierens <39762930+benbierens@users.noreply.github.com> Date: Thu, 30 Jan 2025 17:09:30 +0100 Subject: [PATCH 6/7] Update codex/utils/statsummary.nim Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Signed-off-by: Ben Bierens <39762930+benbierens@users.noreply.github.com> --- codex/utils/statsummary.nim | 18 +++--------------- 1 file changed, 3 insertions(+), 15 deletions(-) diff --git a/codex/utils/statsummary.nim b/codex/utils/statsummary.nim index ff9080e6..dafe85c6 100644 --- a/codex/utils/statsummary.nim +++ b/codex/utils/statsummary.nim @@ -12,21 +12,9 @@ when defined(metrics): return let timestamp = st.now() - output( - name = st.name & "_min", - value = st.min, - timestamp = timestamp - ) - output( - name = st.name & "_max", - value = st.max, - timestamp = timestamp - ) - output( - name = st.name & "_ravg", - value = st.ravg, - timestamp = timestamp - ) + output(name = st.name & "_min", value = st.min, timestamp = timestamp) + output(name = st.name & "_max", value = st.max, timestamp = timestamp) + output(name = st.name & "_ravg", value = st.ravg, timestamp = timestamp) proc declareStatSummary*(name: string, help: string = ""): StatSummary = when defined(metrics): From 8d73da4bcbeb5b28e46c37c1c20d11a8b668895e Mon Sep 17 00:00:00 2001 From: Ben Bierens <39762930+benbierens@users.noreply.github.com> Date: Thu, 30 Jan 2025 17:09:38 +0100 Subject: [PATCH 7/7] Update codex/utils/statsummary.nim Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com> Signed-off-by: Ben Bierens <39762930+benbierens@users.noreply.github.com> --- codex/utils/statsummary.nim | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/codex/utils/statsummary.nim b/codex/utils/statsummary.nim index dafe85c6..21fc22e1 100644 --- a/codex/utils/statsummary.nim +++ b/codex/utils/statsummary.nim @@ -36,7 +36,9 @@ proc observeStatSummary(st: StatSummary, value: float64) = st.max = value st.ravg = value -template observe*(statSummary: StatSummary | type IgnoredCollector, amount: int64 | float64 = 1) = +template observe*( + statSummary: StatSummary | type IgnoredCollector, amount: int64 | float64 = 1 +) = when defined(metrics) and statSummary is not IgnoredCollector: {.gcsafe.}: observeStatSummary(statSummary, amount.float64)