From ce6e7d17b11b33d5dd17123827dda43af553a7eb Mon Sep 17 00:00:00 2001 From: Eugene Kabanov Date: Wed, 8 Jul 2020 19:48:01 +0300 Subject: [PATCH] Make Future tracking and stack traces optional (#108) * Make Future tracking optional via -d:chronosDutureTracking compilation flag. * Stack traces is now optional, use -d:chronosStackTraces. * Fix mistypes and add test for chronosStackTrace option. --- chronos.nimble | 5 +- chronos/asyncfutures2.nim | 154 ++++++++++++++++++++++---------------- chronos/asyncloop.nim | 23 +++--- chronos/asyncmacro2.nim | 4 +- chronos/debugutils.nim | 46 ++++++------ tests/testutils.nim | 118 ++++++++++++++++------------- 6 files changed, 195 insertions(+), 155 deletions(-) diff --git a/chronos.nimble b/chronos.nimble index e9a95c21..bfc55b2e 100644 --- a/chronos.nimble +++ b/chronos.nimble @@ -13,8 +13,9 @@ requires "nim > 0.19.4", task test, "Run all tests": var commands = [ "nim c -r -d:useSysAssert -d:useGcAssert tests/", - "nim c -r tests/", - "nim c -r -d:release tests/" + "nim c -r -d:chronosStackTrace tests/", + "nim c -r -d:release tests/", + "nim c -r -d:release -d:chronosFutureTracking tests/" ] for testname in ["testall"]: for cmd in commands: diff --git a/chronos/asyncfutures2.nim b/chronos/asyncfutures2.nim index e82c89d9..d5490060 100644 --- a/chronos/asyncfutures2.nim +++ b/chronos/asyncfutures2.nim @@ -16,12 +16,10 @@ const LocCreateIndex* = 0 LocCompleteIndex* = 1 -type - # ZAH: This can probably be stored with a cheaper representation - # until the moment it needs to be printed to the screen - # (e.g. seq[StackTraceEntry]) - StackTrace = string +when defined(chronosStackTrace): + type StackTrace = string +type FutureState* {.pure.} = enum Pending, Finished, Cancelled, Failed @@ -32,12 +30,16 @@ type child*: FutureBase state*: FutureState error*: ref Exception ## Stored exception - errorStackTrace*: StackTrace - stackTrace: StackTrace ## For debugging purposes only. mustCancel*: bool id*: int - next*: FutureBase - prev*: FutureBase + + when defined(chronosStackTrace): + errorStackTrace*: StackTrace + stackTrace: StackTrace ## For debugging purposes only. + + when defined(chronosFutureTracking): + next*: FutureBase + prev*: FutureBase # ZAH: we have discussed some possible optimizations where # the future can be stored within the caller's stack frame. @@ -69,26 +71,30 @@ type count*: int var currentID* {.threadvar.}: int -var futureList* {.threadvar.}: FutureList currentID = 0 -futureList = FutureList() + +when defined(chronosFutureTracking): + var futureList* {.threadvar.}: FutureList + futureList = FutureList() template setupFutureBase(loc: ptr SrcLoc) = new(result) result.state = FutureState.Pending - result.stackTrace = getStackTrace() + when defined(chronosStackTrace): + result.stackTrace = getStackTrace() result.id = currentID result.location[LocCreateIndex] = loc currentID.inc() - result.next = nil - result.prev = futureList.tail - if not(isNil(futureList.tail)): - futureList.tail.next = result - futureList.tail = result - if isNil(futureList.head): - futureList.head = result - futureList.count.inc() + when defined(chronosFutureTracking): + result.next = nil + result.prev = futureList.tail + if not(isNil(futureList.tail)): + futureList.tail.next = result + futureList.tail = result + if isNil(futureList.head): + futureList.head = result + futureList.count.inc() proc newFuture[T](loc: ptr SrcLoc): Future[T] = setupFutureBase(loc) @@ -155,15 +161,19 @@ proc failed*(future: FutureBase): bool {.inline.} = ## Determines whether ``future`` completed with an error. result = (future.state == FutureState.Failed) -proc futureDestructor(udata: pointer) {.gcsafe.} = - ## This procedure will be called when Future[T] got finished, cancelled or - ## failed and all Future[T].callbacks are already scheduled and processed. - let future = cast[FutureBase](udata) - if future == futureList.tail: futureList.tail = future.prev - if future == futureList.head: futureList.head = future.next - if not(isNil(future.next)): future.next.prev = future.prev - if not(isNil(future.prev)): future.prev.next = future.next - futureList.count.dec() +when defined(chronosFutureTracking): + proc futureDestructor(udata: pointer) {.gcsafe.} = + ## This procedure will be called when Future[T] got finished, cancelled or + ## failed and all Future[T].callbacks are already scheduled and processed. + let future = cast[FutureBase](udata) + if future == futureList.tail: futureList.tail = future.prev + if future == futureList.head: futureList.head = future.next + if not(isNil(future.next)): future.next.prev = future.prev + if not(isNil(future.prev)): future.prev.next = future.next + futureList.count.dec() + + proc scheduleDestructor(future: FutureBase) {.inline.} = + callSoon(futureDestructor, cast[pointer](future)) proc checkFinished(future: FutureBase, loc: ptr SrcLoc) = ## Checks whether `future` is finished. If it is then raises a @@ -179,10 +189,11 @@ proc checkFinished(future: FutureBase, loc: ptr SrcLoc) = msg.add("\n " & $future.location[LocCompleteIndex]) msg.add("\n Second completion location:") msg.add("\n " & $loc) - msg.add("\n Stack trace to moment of creation:") - msg.add("\n" & indent(future.stackTrace.strip(), 4)) - msg.add("\n Stack trace to moment of secondary completion:") - msg.add("\n" & indent(getStackTrace().strip(), 4)) + when defined(chronosStackTrace): + msg.add("\n Stack trace to moment of creation:") + msg.add("\n" & indent(future.stackTrace.strip(), 4)) + msg.add("\n Stack trace to moment of secondary completion:") + msg.add("\n" & indent(getStackTrace().strip(), 4)) msg.add("\n\n") var err = newException(FutureDefect, msg) err.cause = future @@ -198,9 +209,6 @@ proc call(callbacks: var Deque[AsyncCallback]) = callSoon(item.function, item.udata) dec(count) -proc scheduleDestructor(future: FutureBase) {.inline.} = - callSoon(futureDestructor, cast[pointer](future)) - proc add(callbacks: var Deque[AsyncCallback], item: AsyncCallback) = if len(callbacks) == 0: callbacks = initDeque[AsyncCallback]() @@ -218,7 +226,8 @@ proc complete[T](future: Future[T], val: T, loc: ptr SrcLoc) = future.value = val future.state = FutureState.Finished future.callbacks.call() - scheduleDestructor(FutureBase(future)) + when defined(chronosFutureTracking): + scheduleDestructor(FutureBase(future)) template complete*[T](future: Future[T], val: T) = ## Completes ``future`` with value ``val``. @@ -230,7 +239,8 @@ proc complete(future: Future[void], loc: ptr SrcLoc) = doAssert(isNil(future.error)) future.state = FutureState.Finished future.callbacks.call() - scheduleDestructor(FutureBase(future)) + when defined(chronosFutureTracking): + scheduleDestructor(FutureBase(future)) template complete*(future: Future[void]) = ## Completes a void ``future``. @@ -243,7 +253,8 @@ proc complete[T](future: FutureVar[T], loc: ptr SrcLoc) = doAssert(isNil(fut.error)) fut.state = FutureState.Finished fut.callbacks.call() - scheduleDestructor(FutureBase(future)) + when defined(chronosFutureTracking): + scheduleDestructor(FutureBase(future)) template complete*[T](futvar: FutureVar[T]) = ## Completes a ``FutureVar``. @@ -257,7 +268,8 @@ proc complete[T](futvar: FutureVar[T], val: T, loc: ptr SrcLoc) = fut.state = FutureState.Finished fut.value = val fut.callbacks.call() - scheduleDestructor(FutureBase(fut)) + when defined(chronosFutureTracking): + scheduleDestructor(FutureBase(fut)) template complete*[T](futvar: FutureVar[T], val: T) = ## Completes a ``FutureVar`` with value ``val``. @@ -270,23 +282,32 @@ proc fail[T](future: Future[T], error: ref Exception, loc: ptr SrcLoc) = checkFinished(FutureBase(future), loc) future.state = FutureState.Failed future.error = error - future.errorStackTrace = - if getStackTrace(error) == "": getStackTrace() else: getStackTrace(error) + when defined(chronosStackTrace): + future.errorStackTrace = if getStackTrace(error) == "": + getStackTrace() + else: + getStackTrace(error) future.callbacks.call() - scheduleDestructor(FutureBase(future)) + when defined(chronosFutureTracking): + scheduleDestructor(FutureBase(future)) template fail*[T](future: Future[T], error: ref Exception) = ## Completes ``future`` with ``error``. fail(future, error, getSrcLocation()) +template newCancelledError(): ref CancelledError = + (ref CancelledError)(msg: "Future operation cancelled!") + proc cancelAndSchedule(future: FutureBase, loc: ptr SrcLoc) = if not(future.finished()): checkFinished(future, loc) future.state = FutureState.Cancelled - future.error = newException(CancelledError, "") - future.errorStackTrace = getStackTrace() + future.error = newCancelledError() + when defined(chronosStackTrace): + future.errorStackTrace = getStackTrace() future.callbacks.call() - scheduleDestructor(future) + when defined(chronosFutureTracking): + scheduleDestructor(future) template cancelAndSchedule*[T](future: Future[T]) = cancelAndSchedule(FutureBase(future), getSrcLocation()) @@ -405,33 +426,35 @@ proc `$`*(entries: seq[StackTraceEntry]): string = if hint.len > 0: result.add(spaces(indent+2) & "## " & hint & "\n") -proc injectStacktrace(future: FutureBase) = - const header = "\nAsync traceback:\n" +when defined(chronosStackTrace): + proc injectStacktrace(future: FutureBase) = + const header = "\nAsync traceback:\n" - var exceptionMsg = future.error.msg - if header in exceptionMsg: - # This is messy: extract the original exception message from the msg - # containing the async traceback. - let start = exceptionMsg.find(header) - exceptionMsg = exceptionMsg[0.." & - " and state = " & $item.state & "\n" - res.add(item) + when defined(chronosFutureTracking): + for item in pendingFutures(): + if item.state in filter: + inc(count) + let loc = item.location[LocCreateIndex][] + let procedure = $loc.procedure + let filename = $loc.file + let procname = if len(procedure) == 0: + "\"unspecified\"" + else: + "\"" & procedure & "\"" + let item = "Future[" & $item.id & "] with name " & $procname & + " created at " & "<" & filename & ":" & $loc.line & ">" & + " and state = " & $item.state & "\n" + res.add(item) result = $count & " pending Future[T] objects found:\n" & $res proc pendingFuturesCount*(filter: set[FutureState]): int = @@ -48,11 +49,14 @@ proc pendingFuturesCount*(filter: set[FutureState]): int = ## ## If ``filter`` is equal to ``AllFutureStates`` Operation's complexity is ## O(1), otherwise operation's complexity is O(n). - if filter == AllFutureStates: - pendingFuturesCount() + when defined(chronosFutureTracking): + if filter == AllFutureStates: + pendingFuturesCount() + else: + var res = 0 + for item in pendingFutures(): + if item.state in filter: + inc(res) + res else: - var res = 0 - for item in pendingFutures(): - if item.state in filter: - inc(res) - res + 0 diff --git a/tests/testutils.nim b/tests/testutils.nim index ca76dfef..6d8ff8af 100644 --- a/tests/testutils.nim +++ b/tests/testutils.nim @@ -5,72 +5,82 @@ # Licensed under either of # Apache License, version 2.0, (LICENSE-APACHEv2) # MIT license (LICENSE-MIT) -import unittest, strutils +import unittest import ../chronos when defined(nimHasUsed): {.used.} suite "Asynchronous utilities test suite": - proc getCount(): int = - # This procedure counts number of Future[T] in double-linked list via list - # iteration. - result = 0 - for item in pendingFutures(): - inc(result) + when defined(chronosFutureTracking): + proc getCount(): int = + # This procedure counts number of Future[T] in double-linked list via list + # iteration. + result = 0 + for item in pendingFutures(): + inc(result) test "Future clean and leaks test": - if pendingFuturesCount(WithoutFinished) == 0: - if pendingFuturesCount(OnlyFinished) > 0: - poll() - check pendingFuturesCount() == 0 + when defined(chronosFutureTracking): + if pendingFuturesCount(WithoutFinished) == 0: + if pendingFuturesCount(OnlyFinished) > 0: + poll() + check pendingFuturesCount() == 0 + else: + echo dumpPendingFutures() + check false else: - echo dumpPendingFutures() - check false + skip() test "FutureList basics test": - var fut1 = newFuture[void]() - check: - getCount() == 1 - pendingFuturesCount() == 1 - var fut2 = newFuture[void]() - check: - getCount() == 2 - pendingFuturesCount() == 2 - var fut3 = newFuture[void]() - check: - getCount() == 3 - pendingFuturesCount() == 3 - fut1.complete() - poll() - check: - getCount() == 2 - pendingFuturesCount() == 2 - fut2.fail(newException(ValueError, "")) - poll() - check: - getCount() == 1 - pendingFuturesCount() == 1 - fut3.cancel() - poll() - check: - getCount() == 0 - pendingFuturesCount() == 0 + when defined(chronosFutureTracking): + var fut1 = newFuture[void]() + check: + getCount() == 1 + pendingFuturesCount() == 1 + var fut2 = newFuture[void]() + check: + getCount() == 2 + pendingFuturesCount() == 2 + var fut3 = newFuture[void]() + check: + getCount() == 3 + pendingFuturesCount() == 3 + fut1.complete() + poll() + check: + getCount() == 2 + pendingFuturesCount() == 2 + fut2.fail(newException(ValueError, "")) + poll() + check: + getCount() == 1 + pendingFuturesCount() == 1 + fut3.cancel() + poll() + check: + getCount() == 0 + pendingFuturesCount() == 0 + else: + skip() test "FutureList async procedure test": - proc simpleProc() {.async.} = - await sleepAsync(10.milliseconds) + when defined(chronosFutureTracking): + proc simpleProc() {.async.} = + await sleepAsync(10.milliseconds) - var fut = simpleProc() - check: - getCount() == 2 - pendingFuturesCount() == 2 + var fut = simpleProc() + check: + getCount() == 2 + pendingFuturesCount() == 2 - waitFor fut - check: - getCount() == 1 - pendingFuturesCount() == 1 + waitFor fut + check: + getCount() == 1 + pendingFuturesCount() == 1 - poll() - check: - getCount() == 0 - pendingFuturesCount() == 0 + poll() + check: + getCount() == 0 + pendingFuturesCount() == 0 + else: + skip()