diff --git a/codex.nim b/codex.nim index 073331f1..4224be31 100644 --- a/codex.nim +++ b/codex.nim @@ -19,6 +19,9 @@ import pkg/confutils/toml/std/uri as confTomlUri import pkg/toml_serialization import pkg/libp2p +when defined(chronosFuturesInstrumentation): + import ./codex/utils/asyncprofiler + import ./codex/conf import ./codex/codex import ./codex/units @@ -106,6 +109,18 @@ when isMainModule: notice "Stopping Codex" + let metrics = getFutureSummaryMetrics() + for (k,v) in metrics.pairs(): + let count = v.count + if count > 0: + echo "" + echo "metric: ", $k + echo "count: ", count + echo "avg execTime:\t", v.totalExecTime div count, "\ttotal: ", v.totalExecTime + echo "avg wallTime:\t", v.totalWallTime div count, "\ttotal: ", v.totalWallTime + echo "avg runTime:\t", v.totalRunTime div count, "\ttotal: ", v.totalRunTime + + try: setControlCHook(controlCHandler) except Exception as exc: # TODO Exception diff --git a/codex/utils/asyncprofiler.nim b/codex/utils/asyncprofiler.nim index f3893b26..832392c6 100644 --- a/codex/utils/asyncprofiler.nim +++ b/codex/utils/asyncprofiler.nim @@ -34,91 +34,91 @@ proc getFutureSummaryMetrics*(): Table[ptr SrcLoc, CallbackMetric] {.gcsafe.} = proc setFutureCreate(fut: FutureBase) {.raises: [].} = ## used for setting the duration - let loc = fut.internalLocation[Create] - perFutureMetrics[fut.id] = FutureMetric() - perFutureMetrics.withValue(fut.id, metric): - metric.created = Moment.now() - # echo loc, "; future create " + {.cast(gcsafe).}: + let loc = fut.internalLocation[Create] + perFutureMetrics[fut.id] = FutureMetric() + perFutureMetrics.withValue(fut.id, metric): + metric.created = Moment.now() + # echo loc, "; future create " proc setFutureStart(fut: FutureBase) {.raises: [].} = ## used for setting the duration - let loc = fut.internalLocation[Create] - assert perFutureMetrics.hasKey(fut.id) - perFutureMetrics.withValue(fut.id, metric): - let ts = Moment.now() - metric.start = some ts - metric.blocks.inc() - # echo loc, "; future start: ", metric.initDuration + {.cast(gcsafe).}: + let loc = fut.internalLocation[Create] + assert perFutureMetrics.hasKey(fut.id) + perFutureMetrics.withValue(fut.id, metric): + let ts = Moment.now() + metric.start = some ts + metric.blocks.inc() + # echo loc, "; future start: ", metric.initDuration proc setFuturePause(fut, child: FutureBase) {.raises: [].} = - ## used for setting the duration - let loc = fut.internalLocation[Create] - let childLoc = if child.isNil: nil else: child.internalLocation[Create] - var durationChildren = ZeroDuration - var initDurationChildren = ZeroDuration - if childLoc != nil: - perFutureMetrics.withValue(child.id, metric): - durationChildren = metric.duration - initDurationChildren = metric.initDuration - assert perFutureMetrics.hasKey(fut.id) - perFutureMetrics.withValue(fut.id, metric): - if metric.start.isSome: - let ts = Moment.now() - metric.duration += ts - metric.start.get() - metric.duration -= initDurationChildren - if metric.blocks == 1: - metric.initDuration = ts - metric.created # tricky, - # the first block of a child iterator also - # runs on the parents clock, so we track our first block - # time so any parents can get it - # echo loc, "; child firstBlock time: ", initDurationChildren + {.cast(gcsafe).}: + ## used for setting the duration + let loc = fut.internalLocation[Create] + let childLoc = if child.isNil: nil else: child.internalLocation[Create] + var durationChildren = ZeroDuration + var initDurationChildren = ZeroDuration + if childLoc != nil: + perFutureMetrics.withValue(child.id, metric): + durationChildren = metric.duration + initDurationChildren = metric.initDuration + assert perFutureMetrics.hasKey(fut.id) + perFutureMetrics.withValue(fut.id, metric): + if metric.start.isSome: + let ts = Moment.now() + metric.duration += ts - metric.start.get() + metric.duration -= initDurationChildren + if metric.blocks == 1: + metric.initDuration = ts - metric.created # tricky, + # the first block of a child iterator also + # runs on the parents clock, so we track our first block + # time so any parents can get it + # echo loc, "; child firstBlock time: ", initDurationChildren - metric.durationChildren += durationChildren - metric.start = none Moment - # echo loc, "; future pause ", if childLoc.isNil: "" else: " child: " & $childLoc + metric.durationChildren += durationChildren + metric.start = none Moment + # echo loc, "; future pause ", if childLoc.isNil: "" else: " child: " & $childLoc proc setFutureDuration(fut: FutureBase) {.raises: [].} = - ## used for setting the duration - let loc = fut.internalLocation[Create] - # assert "set duration: " & $loc - var fm: FutureMetric - # assert perFutureMetrics.pop(fut.id, fm) - perFutureMetrics.withValue(fut.id, metric): - fm = metric[] + {.cast(gcsafe).}: + ## used for setting the duration + let loc = fut.internalLocation[Create] + # assert "set duration: " & $loc + var fm: FutureMetric + # assert perFutureMetrics.pop(fut.id, fm) + perFutureMetrics.withValue(fut.id, metric): + fm = metric[] - discard futureSummaryMetrics.hasKeyOrPut(loc, CallbackMetric(minSingleTime: InfiniteDuration)) - futureSummaryMetrics.withValue(loc, metric): - # echo loc, " set duration: ", futureSummaryMetrics.hasKey(loc) - metric.totalExecTime += fm.duration - metric.totalWallTime += Moment.now() - fm.created - metric.totalRunTime += metric.totalExecTime + fm.durationChildren - # echo loc, " child duration: ", fm.durationChildren - metric.count.inc - metric.minSingleTime = min(metric.minSingleTime, fm.duration) - metric.maxSingleTime = max(metric.maxSingleTime, fm.duration) - # handle overflow - if metric.count == metric.count.typeof.high: - metric.totalExecTime = ZeroDuration - metric.count = 0 + discard futureSummaryMetrics.hasKeyOrPut(loc, CallbackMetric(minSingleTime: InfiniteDuration)) + futureSummaryMetrics.withValue(loc, metric): + # echo loc, " set duration: ", futureSummaryMetrics.hasKey(loc) + metric.totalExecTime += fm.duration + metric.totalWallTime += Moment.now() - fm.created + metric.totalRunTime += metric.totalExecTime + fm.durationChildren + # echo loc, " child duration: ", fm.durationChildren + metric.count.inc + metric.minSingleTime = min(metric.minSingleTime, fm.duration) + metric.maxSingleTime = max(metric.maxSingleTime, fm.duration) + # handle overflow + if metric.count == metric.count.typeof.high: + metric.totalExecTime = ZeroDuration + metric.count = 0 onFutureCreate = - proc (f: FutureBase) {.gcsafe, raises: [].} = - {.cast(gcsafe).}: - f.setFutureCreate() + proc (f: FutureBase) {.nimcall, gcsafe, raises: [].} = + f.setFutureCreate() onFutureRunning = - proc (f: FutureBase) {.gcsafe, raises: [].} = - {.cast(gcsafe).}: - f.setFutureStart() + proc (f: FutureBase) {.nimcall, gcsafe, raises: [].} = + f.setFutureStart() onFuturePause = - proc (f, child: FutureBase) {.gcsafe, raises: [].} = - {.cast(gcsafe).}: - # echo "onFuturePause: ", f.pointer.repr, " ch: ", child.pointer.repr - f.setFuturePause(child) + proc (f, child: FutureBase) {.nimcall, gcsafe, raises: [].} = + # echo "onFuturePause: ", f.pointer.repr, " ch: ", child.pointer.repr + f.setFuturePause(child) onFutureStop = - proc (f: FutureBase) {.gcsafe, raises: [].} = - {.cast(gcsafe).}: - f.setFuturePause(nil) - f.setFutureDuration() + proc (f: FutureBase) {.nimcall, gcsafe, raises: [].} = + f.setFuturePause(nil) + f.setFutureDuration() when isMainModule: import std/unittest @@ -154,10 +154,11 @@ when isMainModule: echo "avg wallTime:\t", v.totalWallTime div count, "\ttotal: ", v.totalWallTime echo "avg runTime:\t", v.totalRunTime div count, "\ttotal: ", v.totalRunTime if k.procedure == "simpleAsync1": - check v.totalExecTime >= 150.milliseconds() + echo "v: ", v + check v.totalExecTime >= 100.milliseconds() check v.totalExecTime <= 180.milliseconds() - check v.totalRunTime >= 200.milliseconds() - check v.totalRunTime <= 230.milliseconds() + check v.totalRunTime >= 150.milliseconds() + check v.totalRunTime <= 240.milliseconds() discard echo "" diff --git a/config.nims b/config.nims index cb96cf55..ce7b741c 100644 --- a/config.nims +++ b/config.nims @@ -5,6 +5,7 @@ import std/os const currentDir = currentSourcePath()[0 .. ^(len("config.nims") + 1)] --d:chronosFuturesInstrumentation +--d:release when getEnv("NIMBUS_BUILD_SYSTEM") == "yes" and # BEWARE diff --git a/vendor/nim-chronos b/vendor/nim-chronos index bd656ab6..d0ed08c4 160000 --- a/vendor/nim-chronos +++ b/vendor/nim-chronos @@ -1 +1 @@ -Subproject commit bd656ab6dfa61497533ebd2f38a1a5d98bfa40aa +Subproject commit d0ed08c4a395c9ede3883a470275821cdee75a53