Merge d7912a1f9cc552cd063b4d3e164cd0fc3dc2fe34 into 858101c74cd34ad8115ec995d32d920727b461b8

.github/workflows/docker-dist-tests.yml

@@ -52,7 +52,7 @@ jobs:
     uses: ./.github/workflows/docker-reusable.yml
     needs: get-contracts-hash
     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

codex/stores/repostore/store.nim

@@ -29,6 +29,16 @@ import ../../logutils
 import ../../merkletree
 import ../../utils
 
+const codex_enable_repostore_timinglogs* {.booldefine.} = false
+
+when codex_enable_repostore_timinglogs:
+  import std/monotimes
+  import ../../utils/statsummary
+
+  let
+    getBlockSummary = declareStatSummary("getBlock")
+    putBlockSummary = declareStatSummary("putBlock")
+
 export blocktype, cid
 
 logScope:
@@ -70,6 +80,9 @@ method getBlock*(
     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
@@ -77,7 +90,13 @@ method getBlock*(
 
     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
+    getBlockSummary.observe(durationUs)
+  else:
+    trace "Got block for cid", cid
+
   return Block.new(cid, data, verify = true)
 
 method getBlockAndProof*(
@@ -188,6 +207,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)
 
@@ -207,6 +229,11 @@ method putBlock*(
   else:
     trace "Block already exists"
 
+  when codex_enable_repostore_timinglogs:
+    let durationUs = (getMonoTime().ticks - startTime) div 1000
+    trace "putBlock", durationUs
+    putBlockSummary.observe(durationUs)
+
   return success()
 
 proc delBlockInternal(

codex/utils/statsummary.nim

@@ -0,0 +1,44 @@
+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", 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.hasValues = false
+  else:
+    return IgnoredCollector
+
+proc observeStatSummary(st: StatSummary, value: float64) =
+  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
+    st.max = value
+    st.ravg = value
+
+template observe*(
+    statSummary: StatSummary | type IgnoredCollector, amount: int64 | float64 = 1
+) =
+  when defined(metrics) and statSummary is not IgnoredCollector:
+    {.gcsafe.}:
+      observeStatSummary(statSummary, amount.float64)