From 969559f0071ae4c254744275b29fde0c24322385 Mon Sep 17 00:00:00 2001 From: Raas Ahsan Date: Tue, 11 Aug 2020 02:18:57 -0500 Subject: [PATCH 1/6] stack trace manipulation --- .../effect/internals/TracingPlatform.java | 2 +- .../cats/effect/internals/IOContext.scala | 3 ++ .../cats/effect/internals/IORunLoop.scala | 29 +++++++++++++++++++ .../scala/cats/effect/tracing/IOTrace.scala | 7 ++--- 4 files changed, 36 insertions(+), 5 deletions(-) diff --git a/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java b/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java index 099598e12b..dcbd049718 100644 --- a/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java +++ b/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java @@ -58,6 +58,6 @@ public final class TracingPlatform { return Optional.empty(); } }) - .orElse(128); + .orElse(16); } diff --git a/core/shared/src/main/scala/cats/effect/internals/IOContext.scala b/core/shared/src/main/scala/cats/effect/internals/IOContext.scala index cdfbc129c5..131183d517 100644 --- a/core/shared/src/main/scala/cats/effect/internals/IOContext.scala +++ b/core/shared/src/main/scala/cats/effect/internals/IOContext.scala @@ -38,4 +38,7 @@ final private[effect] class IOContext() { def trace(): IOTrace = IOTrace(events.toList, captured, omitted) + def getStackTraces(): List[Throwable] = + events.toList.collect { case IOEvent.StackTrace(throwable) => throwable } + } diff --git a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala index 582cf439dd..6cfb2ee30d 100644 --- a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala +++ b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala @@ -114,6 +114,35 @@ private[effect] object IORunLoop { catch { case NonFatal(ex) => RaiseError(ex) } case RaiseError(ex) => + def getOpAndCallSite(frames: List[StackTraceElement]): Option[(StackTraceElement, StackTraceElement)] = { + val stackTraceFilter = List( + "cats.effect.", + "cats.", + "sbt.", + "java.", + "sun.", + "scala." + ) + + frames + .sliding(2) + .collect { + case a :: b :: Nil => (a, b) + } + .find { + case (_, callSite) => !stackTraceFilter.exists(callSite.getClassName.startsWith(_)) + } + } + + val prefix = ex.getStackTrace.takeWhile(ste => ste.getClassName != "cats.effect.internals.IORunLoop$" && ste.getClassName != "scala.runtime.java8.JFunction0$mcV$sp") + val asyncTrace = ctx.getStackTraces() + .flatMap(t => getOpAndCallSite(t.getStackTrace.toList)) + .map { + case (methodSite, callSite) => + new StackTraceElement(methodSite.getMethodName + " @ " + callSite.getClassName, callSite.getMethodName, callSite.getFileName, callSite.getLineNumber) + } + val suffix = asyncTrace + ex.setStackTrace(prefix ++ suffix.reverse) findErrorHandler(bFirst, bRest) match { case null => cb(Left(ex)) diff --git a/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala b/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala index 86cffde5d3..7bca733b23 100644 --- a/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala +++ b/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala @@ -33,11 +33,11 @@ final case class IOTrace(events: List[IOEvent], captured: Int, omitted: Int) { val Junction = "├" val Line = "│" + val acc0 = s"IOTrace: $captured frames captured, $omitted omitted\n" if (options.showFullStackTraces) { val stackTraces = events.collect { case e: IOEvent.StackTrace => e } - val header = s"IOTrace: $captured frames captured, $omitted omitted\n" - val body = stackTraces.zipWithIndex + val acc1 = stackTraces.zipWithIndex .map { case (st, index) => val tag = getOpAndCallSite(st.stackTrace) @@ -62,9 +62,8 @@ final case class IOTrace(events: List[IOEvent], captured: Int, omitted: Int) { } .mkString("\n") - header + body + acc0 + acc1 } else { - val acc0 = s"IOTrace: $captured frames captured, $omitted omitted\n" val acc1 = events.zipWithIndex .map { case (event, index) => From e032a7b1f2aea2b726110e0ee55b4d57a7190442 Mon Sep 17 00:00:00 2001 From: Raas Ahsan Date: Tue, 11 Aug 2020 22:10:50 -0500 Subject: [PATCH 2/6] reverse printFiberTrace order --- .../cats/effect/internals/IORunLoop.scala | 12 ++++++++--- .../cats/effect/internals/RingBuffer.scala | 7 ++++--- .../scala/cats/effect/tracing/IOTrace.scala | 20 +++++++++++++------ 3 files changed, 27 insertions(+), 12 deletions(-) diff --git a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala index 6cfb2ee30d..2c376de9d3 100644 --- a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala +++ b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala @@ -134,12 +134,18 @@ private[effect] object IORunLoop { } } - val prefix = ex.getStackTrace.takeWhile(ste => ste.getClassName != "cats.effect.internals.IORunLoop$" && ste.getClassName != "scala.runtime.java8.JFunction0$mcV$sp") - val asyncTrace = ctx.getStackTraces() + val prefix = ex.getStackTrace.takeWhile(ste => + ste.getClassName != "cats.effect.internals.IORunLoop$" && ste.getClassName != "scala.runtime.java8.JFunction0$mcV$sp" + ) + val asyncTrace = ctx + .getStackTraces() .flatMap(t => getOpAndCallSite(t.getStackTrace.toList)) .map { case (methodSite, callSite) => - new StackTraceElement(methodSite.getMethodName + " @ " + callSite.getClassName, callSite.getMethodName, callSite.getFileName, callSite.getLineNumber) + new StackTraceElement(methodSite.getMethodName + " @ " + callSite.getClassName, + callSite.getMethodName, + callSite.getFileName, + callSite.getLineNumber) } val suffix = asyncTrace ex.setStackTrace(prefix ++ suffix.reverse) diff --git a/core/shared/src/main/scala/cats/effect/internals/RingBuffer.scala b/core/shared/src/main/scala/cats/effect/internals/RingBuffer.scala index 93b1e094f6..4e4af774ea 100644 --- a/core/shared/src/main/scala/cats/effect/internals/RingBuffer.scala +++ b/core/shared/src/main/scala/cats/effect/internals/RingBuffer.scala @@ -46,10 +46,11 @@ final private[internals] class RingBuffer[A <: AnyRef](size: Int) { def capacity: Int = length + // returns a list in reverse order of insertion def toList: List[A] = { - val end = index - val start = Math.max(end - length, 0) - (start until end).toList + val start = index - 1 + val end = Math.max(start - length, 0) + (start to end by -1).toList .map(i => array(i & mask).asInstanceOf[A]) } diff --git a/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala b/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala index 7bca733b23..0fe5222fc1 100644 --- a/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala +++ b/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala @@ -33,7 +33,7 @@ final case class IOTrace(events: List[IOEvent], captured: Int, omitted: Int) { val Junction = "├" val Line = "│" - val acc0 = s"IOTrace: $captured frames captured, $omitted omitted\n" + val acc0 = s"IOTrace: $captured frames captured\n" if (options.showFullStackTraces) { val stackTraces = events.collect { case e: IOEvent.StackTrace => e } @@ -62,12 +62,16 @@ final case class IOTrace(events: List[IOEvent], captured: Int, omitted: Int) { } .mkString("\n") - acc0 + acc1 + val acc2 = if (omitted > 0) { + "\n" + TurnRight + s" ... ($omitted frames omitted)\n" + } else "\n" + + acc0 + acc1 + acc2 } else { val acc1 = events.zipWithIndex .map { case (event, index) => - val junc = if (index == events.length - 1) TurnRight else Junction + val junc = if (index == events.length - 1 && omitted == 0) TurnRight else Junction val message = event match { case ev: IOEvent.StackTrace => { getOpAndCallSite(ev.stackTrace) @@ -75,16 +79,20 @@ final case class IOTrace(events: List[IOEvent], captured: Int, omitted: Int) { case (methodSite, callSite) => val loc = renderStackTraceElement(callSite) val op = NameTransformer.decode(methodSite.getMethodName) - s"$op at $loc" + s"$op @ $loc" } .getOrElse("(...)") } } s" $junc $message" } - .mkString(acc0, "\n", "\n") + .mkString(acc0, "\n", "") + + val acc2 = if (omitted > 0) { + acc1 + "\n " + TurnRight + s" ... ($omitted frames omitted)" + } else acc1 - acc1 + acc2 + "\n" } } } From be33127fffcb22ca8132ad403d7082bdaa9230d9 Mon Sep 17 00:00:00 2001 From: Raas Ahsan Date: Tue, 11 Aug 2020 22:40:45 -0500 Subject: [PATCH 3/6] configuration and augmentException --- .../effect/internals/TracingPlatform.scala | 2 + .../effect/internals/TracingPlatform.java | 12 +++- .../cats/effect/internals/IORunLoop.scala | 63 ++++++++----------- .../scala/cats/effect/tracing/IOTrace.scala | 47 +++++++------- 4 files changed, 66 insertions(+), 58 deletions(-) diff --git a/core/js/src/main/scala/cats/effect/internals/TracingPlatform.scala b/core/js/src/main/scala/cats/effect/internals/TracingPlatform.scala index 3a9decc42e..c3b3e73af1 100644 --- a/core/js/src/main/scala/cats/effect/internals/TracingPlatform.scala +++ b/core/js/src/main/scala/cats/effect/internals/TracingPlatform.scala @@ -24,4 +24,6 @@ object TracingPlatform { final val isStackTracing: Boolean = isFullStackTracing || isCachedStackTracing final val traceBufferSize: Int = 32 + + final val contextualExceptions: Boolean = false } diff --git a/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java b/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java index dcbd049718..f56f7bfa1f 100644 --- a/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java +++ b/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java @@ -36,7 +36,7 @@ public final class TracingPlatform { */ private static final String stackTracingMode = Optional.ofNullable(System.getProperty("cats.effect.stackTracingMode")) .filter(x -> !x.isEmpty()) - .orElse("cached"); + .orElse("full"); public static final boolean isCachedStackTracing = stackTracingMode.equalsIgnoreCase("cached"); @@ -60,4 +60,14 @@ public final class TracingPlatform { }) .orElse(16); + /** + * Sets the contextual exceptions flag, which controls whether or not the + * stack traces of IO exceptions are augmented to include async stack trace information. + * Stack tracing must be enabled in order to use this feature. + * This flag is enabled by default. + */ + public static final boolean contextualExceptions = Optional.ofNullable(System.getProperty("cats.effect.contextualExceptions")) + .map(x -> Boolean.valueOf(x)) + .orElse(true); + } diff --git a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala index 2c376de9d3..5692fe31b0 100644 --- a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala +++ b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala @@ -18,8 +18,8 @@ package cats.effect.internals import cats.effect.IO import cats.effect.IO.{Async, Bind, ContextSwitch, Delay, Map, Pure, RaiseError, Suspend, Trace} -import cats.effect.tracing.IOEvent -import cats.effect.internals.TracingPlatform.isStackTracing +import cats.effect.tracing.{IOEvent, IOTrace} +import cats.effect.internals.TracingPlatform.{contextualExceptions, isStackTracing} import scala.util.control.NonFatal @@ -114,41 +114,9 @@ private[effect] object IORunLoop { catch { case NonFatal(ex) => RaiseError(ex) } case RaiseError(ex) => - def getOpAndCallSite(frames: List[StackTraceElement]): Option[(StackTraceElement, StackTraceElement)] = { - val stackTraceFilter = List( - "cats.effect.", - "cats.", - "sbt.", - "java.", - "sun.", - "scala." - ) - - frames - .sliding(2) - .collect { - case a :: b :: Nil => (a, b) - } - .find { - case (_, callSite) => !stackTraceFilter.exists(callSite.getClassName.startsWith(_)) - } + if (isStackTracing && contextualExceptions) { + augmentException(ex, ctx) } - - val prefix = ex.getStackTrace.takeWhile(ste => - ste.getClassName != "cats.effect.internals.IORunLoop$" && ste.getClassName != "scala.runtime.java8.JFunction0$mcV$sp" - ) - val asyncTrace = ctx - .getStackTraces() - .flatMap(t => getOpAndCallSite(t.getStackTrace.toList)) - .map { - case (methodSite, callSite) => - new StackTraceElement(methodSite.getMethodName + " @ " + callSite.getClassName, - callSite.getMethodName, - callSite.getFileName, - callSite.getLineNumber) - } - val suffix = asyncTrace - ex.setStackTrace(prefix ++ suffix.reverse) findErrorHandler(bFirst, bRest) match { case null => cb(Left(ex)) @@ -279,6 +247,9 @@ private[effect] object IORunLoop { } catch { case NonFatal(ex) => RaiseError(ex) } case RaiseError(ex) => + if (isStackTracing && contextualExceptions) { + augmentException(ex, ctx) + } findErrorHandler(bFirst, bRest) match { case null => return currentIO.asInstanceOf[IO[A]] @@ -392,6 +363,26 @@ private[effect] object IORunLoop { } } + /** + * If stack tracing and contextual exceptions are enabled, this + * function will rewrite the stack trace of a captured exception + * to include the async stack trace. + */ + private def augmentException(ex: Throwable, ctx: IOContext): Unit = { + val prefix = IOTrace.dropRunLoopSuffix(ex.getStackTrace.toList) + val suffix = ctx + .getStackTraces() + .flatMap(t => IOTrace.getOpAndCallSite(t.getStackTrace.toList)) + .map { + case (methodSite, callSite) => + new StackTraceElement(methodSite.getMethodName + " @ " + callSite.getClassName, + callSite.getMethodName, + callSite.getFileName, + callSite.getLineNumber) + } + ex.setStackTrace((prefix ++ suffix).toArray) + } + /** * A `RestartCallback` gets created only once, per [[startCancelable]] * (`unsafeRunAsync`) invocation, once an `Async` state is hit, diff --git a/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala b/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala index 0fe5222fc1..6f01baa28d 100644 --- a/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala +++ b/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala @@ -64,7 +64,7 @@ final case class IOTrace(events: List[IOEvent], captured: Int, omitted: Int) { val acc2 = if (omitted > 0) { "\n" + TurnRight + s" ... ($omitted frames omitted)\n" - } else "\n" + } else "\n" + TurnRight + "\n" acc0 + acc1 + acc2 } else { @@ -99,26 +99,7 @@ final case class IOTrace(events: List[IOEvent], captured: Int, omitted: Int) { private[effect] object IOTrace { - // Number of lines to drop from the top of the stack trace - def stackTraceIgnoreLines = 3 - - private[this] val anonfunRegex = "^\\$+anonfun\\$+(.+)\\$+\\d+$".r - - private[this] val stackTraceFilter = List( - "cats.effect.", - "cats.", - "sbt.", - "java.", - "sun.", - "scala." - ) - - private def renderStackTraceElement(ste: StackTraceElement): String = { - val methodName = demangleMethod(ste.getMethodName) - s"${ste.getClassName}.$methodName (${ste.getFileName}:${ste.getLineNumber})" - } - - private def getOpAndCallSite(frames: List[StackTraceElement]): Option[(StackTraceElement, StackTraceElement)] = + def getOpAndCallSite(frames: List[StackTraceElement]): Option[(StackTraceElement, StackTraceElement)] = frames .sliding(2) .collect { @@ -128,9 +109,33 @@ private[effect] object IOTrace { case (_, callSite) => !stackTraceFilter.exists(callSite.getClassName.startsWith(_)) } + def dropRunLoopSuffix(frames: List[StackTraceElement]): List[StackTraceElement] = + frames.takeWhile(ste => !contextualFilter.exists(ste.getClassName.startsWith(_))) + + private def renderStackTraceElement(ste: StackTraceElement): String = { + val methodName = demangleMethod(ste.getMethodName) + s"${ste.getClassName}.$methodName (${ste.getFileName}:${ste.getLineNumber})" + } + private def demangleMethod(methodName: String): String = anonfunRegex.findFirstMatchIn(methodName) match { case Some(mat) => mat.group(1) case None => methodName } + + private[this] val anonfunRegex = "^\\$+anonfun\\$+(.+)\\$+\\d+$".r + + private[this] val stackTraceFilter = List( + "cats.effect.", + "cats.", + "sbt.", + "java.", + "sun.", + "scala." + ) + + private[this] val contextualFilter = List( + "cats.effect.", + "scala." + ) } From ccedb18adbac13ef382e33154ba83ece88b2a36c Mon Sep 17 00:00:00 2001 From: Raas Ahsan Date: Tue, 11 Aug 2020 23:11:26 -0500 Subject: [PATCH 4/6] Documentation --- .../effect/internals/TracingPlatform.java | 2 +- .../cats/effect/internals/IORunLoop.scala | 28 +++-- site/src/main/mdoc/tracing/index.md | 105 ++++++++++++++---- 3 files changed, 99 insertions(+), 36 deletions(-) diff --git a/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java b/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java index f56f7bfa1f..127e9bf9e8 100644 --- a/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java +++ b/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java @@ -36,7 +36,7 @@ public final class TracingPlatform { */ private static final String stackTracingMode = Optional.ofNullable(System.getProperty("cats.effect.stackTracingMode")) .filter(x -> !x.isEmpty()) - .orElse("full"); + .orElse("cached"); public static final boolean isCachedStackTracing = stackTracingMode.equalsIgnoreCase("cached"); diff --git a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala index 5692fe31b0..e1a2a3c068 100644 --- a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala +++ b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala @@ -369,18 +369,22 @@ private[effect] object IORunLoop { * to include the async stack trace. */ private def augmentException(ex: Throwable, ctx: IOContext): Unit = { - val prefix = IOTrace.dropRunLoopSuffix(ex.getStackTrace.toList) - val suffix = ctx - .getStackTraces() - .flatMap(t => IOTrace.getOpAndCallSite(t.getStackTrace.toList)) - .map { - case (methodSite, callSite) => - new StackTraceElement(methodSite.getMethodName + " @ " + callSite.getClassName, - callSite.getMethodName, - callSite.getFileName, - callSite.getLineNumber) - } - ex.setStackTrace((prefix ++ suffix).toArray) + val stackTrace = ex.getStackTrace + if (!stackTrace.isEmpty) { + val prefix = IOTrace.dropRunLoopSuffix(stackTrace.toList) + val suffix = ctx + .getStackTraces() + // TODO: We should just store a List[StackTraceElement] in the cache + .flatMap(t => IOTrace.getOpAndCallSite(t.getStackTrace.toList)) + .map { + case (methodSite, callSite) => + new StackTraceElement(methodSite.getMethodName + " @ " + callSite.getClassName, + callSite.getMethodName, + callSite.getFileName, + callSite.getLineNumber) + } + ex.setStackTrace((prefix ++ suffix).toArray) + } } /** diff --git a/site/src/main/mdoc/tracing/index.md b/site/src/main/mdoc/tracing/index.md index 99f6e6ab08..cbfa5045b3 100644 --- a/site/src/main/mdoc/tracing/index.md +++ b/site/src/main/mdoc/tracing/index.md @@ -26,20 +26,25 @@ coherent view of the fiber's execution path. For example, here is a trace of a sample program that is running in cached stack tracing mode: ``` -IOTrace: 13 frames captured, 0 omitted - ├ flatMap at org.simpleapp.example.Example.run (Example.scala:67) - ├ flatMap at org.simpleapp.example.Example.program (Example.scala:57) - ├ flatMap at org.simpleapp.example.Example.program (Example.scala:58) - ├ flatMap at org.simpleapp.example.Example.program (Example.scala:59) - ├ flatMap at org.simpleapp.example.Example.program (Example.scala:60) - ├ async at org.simpleapp.example.Example.program (Example.scala:60) - ├ flatMap at org.simpleapp.example.Example.program (Example.scala:61) - ├ flatMap at org.simpleapp.example.Example.program (Example.scala:60) - ├ flatMap at org.simpleapp.example.Example.program2 (Example.scala:51) - ├ map at org.simpleapp.example.Example.program2 (Example.scala:52) - ├ map at org.simpleapp.example.Example.program (Example.scala:60) - ├ map at org.simpleapp.example.Example.program (Example.scala:62) - ╰ flatMap at org.simpleapp.example.Example.run (Example.scala:67) +IOTrace: 19 frames captured + ├ flatMap @ org.simpleapp.examples.Main$.program (Main.scala:53) + ├ map @ org.simpleapp.examples.Main$.foo (Main.scala:46) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:45) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:44) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:43) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:42) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:41) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:40) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:39) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:38) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:37) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:36) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:35) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:34) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:33) + ├ flatMap @ org.simpleapp.examples.Main$.foo (Main.scala:32) + ├ flatMap @ org.simpleapp.examples.Main$.program (Main.scala:53) + ╰ ... (3 frames omitted) ``` However, fiber tracing isn't limited to collecting stack traces. Tracing @@ -54,32 +59,34 @@ fiber. combinator was actually called by user code. For example, `void` and `as` are combinators that are derived from `map`, and should appear in the fiber trace rather than `map`. -3. Intermediate values. The intermediate values that an `IO` program encounters +3. **Contextual exceptions**. Exceptions captured by the `IO` runtime can be +augmented with async stack traces to produce more relevant stack traces. +4. Intermediate values. The intermediate values that an `IO` program encounters can be converted to a string to render. This can aid in understanding the actions that a program takes. -4. Thread tracking. A fiber is scheduled on potentially many threads throughout +5. Thread tracking. A fiber is scheduled on potentially many threads throughout its lifetime. Knowing what thread a fiber is running on, and when it shifts threads is a powerful tool for understanding and debugging the concurrency of an application. -5. Tree rendering. By collecting a trace of all `IO` operations, a pretty tree +6. Tree rendering. By collecting a trace of all `IO` operations, a pretty tree or graph can be rendered to visualize fiber execution. -6. Fiber identity. Fibers, like threads, are unique and can therefore assume an +7. Fiber identity. Fibers, like threads, are unique and can therefore assume an identity. If user code can observe fiber identity, powerful observability tools can be built on top of it. For example, another shortcoming of asynchronous code is that it becomes tedious to correlate log messages across asynchronous boundaries (thread IDs aren't very useful). With fiber identity, log messages produced by a single fiber can be associated with a unique, stable identifier. -7. Fiber ancestry graph. If fibers can assume an identity, an ancestry graph +8. Fiber ancestry graph. If fibers can assume an identity, an ancestry graph can be formed, where nodes are fibers and edges represent a fork/join relationship. -8. Asynchronous deadlock detection. Even when working with asynchronously +9. Asynchronous deadlock detection. Even when working with asynchronously blocking code, fiber deadlocks aren't impossible. Being able to detect deadlocks or infer when a deadlock can happen makes writing concurrent code much easier. -9. Live fiber trace dumps. Similar to JVM thread dumps, the execution status +10. Live fiber trace dumps. Similar to JVM thread dumps, the execution status and trace information of all fibers in an application can be extracted for debugging purposes. -10. Monad transformer analysis. +11. Monad transformer analysis. As note of caution, fiber tracing generally introduces overhead to applications in the form of higher CPU usage, memory and GC pressure. @@ -95,7 +102,7 @@ The stack tracing mode of an application is configured by the system property To prevent unbounded memory usage, stack traces for a fiber are accumulated in an internal buffer as execution proceeds. If more traces are collected than the buffer can retain, then the older traces will be overwritten. The default -size for the buffer is 128, but can be changed via the system property +size for the buffer is 32, but can be changed via the system property `cats.effect.traceBufferSize`. Keep in mind that the buffer size will always be rounded up to a power of 2. @@ -163,6 +170,58 @@ def program: IO[Unit] = Keep in mind that the scope and amount of information that traces hold will change over time as additional fiber tracing features are merged into master. +## Contextual exceptions +The stack trace of an exception caught by the IO runloop looks similar to the +following output: +``` +java.lang.Throwable: A runtime exception has occurred + at org.simpleapp.examples.Main$.b(Main.scala:28) + at org.simpleapp.examples.Main$.a(Main.scala:25) + at org.simpleapp.examples.Main$.$anonfun$foo$11(Main.scala:37) + at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18) + at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:103) + at cats.effect.internals.IORunLoop$RestartCallback.signal(IORunLoop.scala:440) + at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:461) + at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:399) + at cats.effect.internals.IOShift$Tick.run(IOShift.scala:36) + at cats.effect.internals.PoolUtils$$anon$2$$anon$3.run(PoolUtils.scala:52) + at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) + at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) + at java.lang.Thread.run(Thread.java:748) +``` + +It includes stack frames that are part of the IO runloop, which are generally +not of interest to users of the library. When asynchronous stack tracing is +enabled, the IO runloop is capable of augmenting the stack traces of caught +exceptions to include frames from the asynchronous stack traces. For example, +the augmented version of the above stack trace looks like the following: +``` +java.lang.Throwable: A runtime exception has occurred + at org.simpleapp.examples.Main$.b(Main.scala:28) + at org.simpleapp.examples.Main$.a(Main.scala:25) + at org.simpleapp.examples.Main$.$anonfun$foo$11(Main.scala:37) + at map @ org.simpleapp.examples.Main$.$anonfun$foo$10(Main.scala:37) + at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$8(Main.scala:36) + at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$6(Main.scala:35) + at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$4(Main.scala:34) + at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$2(Main.scala:33) + at flatMap @ org.simpleapp.examples.Main$.foo(Main.scala:32) + at flatMap @ org.simpleapp.examples.Main$.program(Main.scala:42) + at as @ org.simpleapp.examples.Main$.run(Main.scala:48) + at main$ @ org.simpleapp.examples.Main$.main(Main.scala:22) +``` + +Note that the relevant stack frames from the call-site of the user code +is preserved, but all IO-related stack frames are replaced with async +stack trace frames. + +This feature is controlled by the system property +`cats.effect.contextualExceptions`. It is enabled by default. + +``` +-Dcats.effect.stackTracingMode=false +``` + ### Complete example Here is a sample program that demonstrates tracing in action. From a7a0e4e89d5d4141647113ee3c4f58059fa556df Mon Sep 17 00:00:00 2001 From: Raas Ahsan Date: Thu, 13 Aug 2020 23:46:55 -0500 Subject: [PATCH 5/6] address pr feedback --- .../effect/internals/TracingPlatform.scala | 2 +- .../effect/internals/TracingPlatform.java | 4 +- .../cats/effect/internals/IOContext.scala | 4 +- .../cats/effect/internals/IORunLoop.scala | 45 ++++++++++++------- .../cats/effect/internals/IOTracing.scala | 2 +- .../cats/effect/internals/RingBuffer.scala | 2 +- .../scala/cats/effect/tracing/IOEvent.scala | 5 +-- .../scala/cats/effect/tracing/IOTrace.scala | 8 ---- .../effect/internals/IOContextTests.scala | 8 ++-- .../effect/internals/RingBufferTests.scala | 4 +- .../test/scala/cats/effect/TracingTests.scala | 20 +++++++++ site/src/main/mdoc/tracing/index.md | 6 +-- 12 files changed, 66 insertions(+), 44 deletions(-) diff --git a/core/js/src/main/scala/cats/effect/internals/TracingPlatform.scala b/core/js/src/main/scala/cats/effect/internals/TracingPlatform.scala index c3b3e73af1..b4ba1f8f62 100644 --- a/core/js/src/main/scala/cats/effect/internals/TracingPlatform.scala +++ b/core/js/src/main/scala/cats/effect/internals/TracingPlatform.scala @@ -25,5 +25,5 @@ object TracingPlatform { final val traceBufferSize: Int = 32 - final val contextualExceptions: Boolean = false + final val enhancedExceptions: Boolean = false } diff --git a/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java b/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java index 127e9bf9e8..8d6736686f 100644 --- a/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java +++ b/core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java @@ -61,12 +61,12 @@ public final class TracingPlatform { .orElse(16); /** - * Sets the contextual exceptions flag, which controls whether or not the + * Sets the enhanced exceptions flag, which controls whether or not the * stack traces of IO exceptions are augmented to include async stack trace information. * Stack tracing must be enabled in order to use this feature. * This flag is enabled by default. */ - public static final boolean contextualExceptions = Optional.ofNullable(System.getProperty("cats.effect.contextualExceptions")) + public static final boolean enhancedExceptions = Optional.ofNullable(System.getProperty("cats.effect.enhancedExceptions")) .map(x -> Boolean.valueOf(x)) .orElse(true); diff --git a/core/shared/src/main/scala/cats/effect/internals/IOContext.scala b/core/shared/src/main/scala/cats/effect/internals/IOContext.scala index 131183d517..12ac10e762 100644 --- a/core/shared/src/main/scala/cats/effect/internals/IOContext.scala +++ b/core/shared/src/main/scala/cats/effect/internals/IOContext.scala @@ -38,7 +38,7 @@ final private[effect] class IOContext() { def trace(): IOTrace = IOTrace(events.toList, captured, omitted) - def getStackTraces(): List[Throwable] = - events.toList.collect { case IOEvent.StackTrace(throwable) => throwable } + def getStackTraces(): List[IOEvent.StackTrace] = + events.toList.collect { case ev: IOEvent.StackTrace => ev } } diff --git a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala index e1a2a3c068..c366a4a73f 100644 --- a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala +++ b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala @@ -19,7 +19,7 @@ package cats.effect.internals import cats.effect.IO import cats.effect.IO.{Async, Bind, ContextSwitch, Delay, Map, Pure, RaiseError, Suspend, Trace} import cats.effect.tracing.{IOEvent, IOTrace} -import cats.effect.internals.TracingPlatform.{contextualExceptions, isStackTracing} +import cats.effect.internals.TracingPlatform.{enhancedExceptions, isStackTracing} import scala.util.control.NonFatal @@ -114,7 +114,7 @@ private[effect] object IORunLoop { catch { case NonFatal(ex) => RaiseError(ex) } case RaiseError(ex) => - if (isStackTracing && contextualExceptions) { + if (isStackTracing && enhancedExceptions) { augmentException(ex, ctx) } findErrorHandler(bFirst, bRest) match { @@ -247,7 +247,7 @@ private[effect] object IORunLoop { } catch { case NonFatal(ex) => RaiseError(ex) } case RaiseError(ex) => - if (isStackTracing && contextualExceptions) { + if (isStackTracing && enhancedExceptions) { augmentException(ex, ctx) } findErrorHandler(bFirst, bRest) match { @@ -371,22 +371,35 @@ private[effect] object IORunLoop { private def augmentException(ex: Throwable, ctx: IOContext): Unit = { val stackTrace = ex.getStackTrace if (!stackTrace.isEmpty) { - val prefix = IOTrace.dropRunLoopSuffix(stackTrace.toList) - val suffix = ctx - .getStackTraces() - // TODO: We should just store a List[StackTraceElement] in the cache - .flatMap(t => IOTrace.getOpAndCallSite(t.getStackTrace.toList)) - .map { - case (methodSite, callSite) => - new StackTraceElement(methodSite.getMethodName + " @ " + callSite.getClassName, - callSite.getMethodName, - callSite.getFileName, - callSite.getLineNumber) - } - ex.setStackTrace((prefix ++ suffix).toArray) + val augmented = stackTrace(stackTrace.length - 1) eq augmentationMarker + if (!augmented) { + val prefix = dropRunLoopFrames(stackTrace) + val suffix = ctx + .getStackTraces() + .flatMap(t => IOTrace.getOpAndCallSite(t.stackTrace)) + .map { + case (methodSite, callSite) => + new StackTraceElement(methodSite.getMethodName + " @ " + callSite.getClassName, + callSite.getMethodName, + callSite.getFileName, + callSite.getLineNumber) + } + .toArray + ex.setStackTrace(prefix ++ suffix ++ Array(augmentationMarker)) + } } } + private def dropRunLoopFrames(frames: Array[StackTraceElement]): Array[StackTraceElement] = + frames.takeWhile(ste => !runLoopFilter.exists(ste.getClassName.startsWith(_))) + + private[this] val runLoopFilter = List( + "cats.effect.", + "scala." + ) + + private[this] val augmentationMarker = new StackTraceElement("", "", "", 0) + /** * A `RestartCallback` gets created only once, per [[startCancelable]] * (`unsafeRunAsync`) invocation, once an `Async` state is hit, diff --git a/core/shared/src/main/scala/cats/effect/internals/IOTracing.scala b/core/shared/src/main/scala/cats/effect/internals/IOTracing.scala index 171495d14e..e5eba141e1 100644 --- a/core/shared/src/main/scala/cats/effect/internals/IOTracing.scala +++ b/core/shared/src/main/scala/cats/effect/internals/IOTracing.scala @@ -45,7 +45,7 @@ private[effect] object IOTracing { } private def buildFrame(): IOEvent = - IOEvent.StackTrace(new Throwable()) + IOEvent.StackTrace(new Throwable().getStackTrace.toList) /** * Global cache for trace frames. Keys are references to lambda classes. diff --git a/core/shared/src/main/scala/cats/effect/internals/RingBuffer.scala b/core/shared/src/main/scala/cats/effect/internals/RingBuffer.scala index 4e4af774ea..2b6efcdd5e 100644 --- a/core/shared/src/main/scala/cats/effect/internals/RingBuffer.scala +++ b/core/shared/src/main/scala/cats/effect/internals/RingBuffer.scala @@ -49,7 +49,7 @@ final private[internals] class RingBuffer[A <: AnyRef](size: Int) { // returns a list in reverse order of insertion def toList: List[A] = { val start = index - 1 - val end = Math.max(start - length, 0) + val end = Math.max(index - length, 0) (start to end by -1).toList .map(i => array(i & mask).asInstanceOf[A]) } diff --git a/core/shared/src/main/scala/cats/effect/tracing/IOEvent.scala b/core/shared/src/main/scala/cats/effect/tracing/IOEvent.scala index b23c1b3266..111cafac58 100644 --- a/core/shared/src/main/scala/cats/effect/tracing/IOEvent.scala +++ b/core/shared/src/main/scala/cats/effect/tracing/IOEvent.scala @@ -20,9 +20,6 @@ sealed abstract class IOEvent object IOEvent { - final case class StackTrace(throwable: Throwable) extends IOEvent { - def stackTrace: List[StackTraceElement] = - throwable.getStackTrace().toList - } + final case class StackTrace(stackTrace: List[StackTraceElement]) extends IOEvent } diff --git a/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala b/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala index 6f01baa28d..5c2c525cce 100644 --- a/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala +++ b/core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala @@ -109,9 +109,6 @@ private[effect] object IOTrace { case (_, callSite) => !stackTraceFilter.exists(callSite.getClassName.startsWith(_)) } - def dropRunLoopSuffix(frames: List[StackTraceElement]): List[StackTraceElement] = - frames.takeWhile(ste => !contextualFilter.exists(ste.getClassName.startsWith(_))) - private def renderStackTraceElement(ste: StackTraceElement): String = { val methodName = demangleMethod(ste.getMethodName) s"${ste.getClassName}.$methodName (${ste.getFileName}:${ste.getLineNumber})" @@ -133,9 +130,4 @@ private[effect] object IOTrace { "sun.", "scala." ) - - private[this] val contextualFilter = List( - "cats.effect.", - "scala." - ) } diff --git a/core/shared/src/test/scala/cats/effect/internals/IOContextTests.scala b/core/shared/src/test/scala/cats/effect/internals/IOContextTests.scala index 4bf304ddc7..8167ba40ff 100644 --- a/core/shared/src/test/scala/cats/effect/internals/IOContextTests.scala +++ b/core/shared/src/test/scala/cats/effect/internals/IOContextTests.scala @@ -23,13 +23,13 @@ import org.scalatest.funsuite.AnyFunSuite class IOContextTests extends AnyFunSuite with Matchers { val traceBufferSize: Int = cats.effect.internals.TracingPlatform.traceBufferSize - val throwable = new Throwable() + val stackTrace = new Throwable().getStackTrace.toList test("push traces") { val ctx = new IOContext() - val t1 = IOEvent.StackTrace(throwable) - val t2 = IOEvent.StackTrace(throwable) + val t1 = IOEvent.StackTrace(stackTrace) + val t2 = IOEvent.StackTrace(stackTrace) ctx.pushEvent(t1) ctx.pushEvent(t2) @@ -44,7 +44,7 @@ class IOContextTests extends AnyFunSuite with Matchers { val ctx = new IOContext() for (_ <- 0 until (traceBufferSize + 10)) { - ctx.pushEvent(IOEvent.StackTrace(throwable)) + ctx.pushEvent(IOEvent.StackTrace(stackTrace)) } val trace = ctx.trace() diff --git a/core/shared/src/test/scala/cats/effect/internals/RingBufferTests.scala b/core/shared/src/test/scala/cats/effect/internals/RingBufferTests.scala index e10f74d049..3b9c55baa2 100644 --- a/core/shared/src/test/scala/cats/effect/internals/RingBufferTests.scala +++ b/core/shared/src/test/scala/cats/effect/internals/RingBufferTests.scala @@ -43,12 +43,12 @@ class RingBufferTests extends AnyFunSuite with Matchers with TestUtils { test("writing elements") { val buffer = new RingBuffer[Integer](4) for (i <- 0 to 3) buffer.push(i) - buffer.toList shouldBe List(0, 1, 2, 3) + buffer.toList shouldBe List(3, 2, 1, 0) } test("overwriting elements") { val buffer = new RingBuffer[Integer](4) for (i <- 0 to 100) buffer.push(i) - buffer.toList shouldBe List(97, 98, 99, 100) + buffer.toList shouldBe List(100, 99, 98, 97) } } diff --git a/runtime-tests/src/test/scala/cats/effect/TracingTests.scala b/runtime-tests/src/test/scala/cats/effect/TracingTests.scala index 4518089439..a4bd20eb34 100644 --- a/runtime-tests/src/test/scala/cats/effect/TracingTests.scala +++ b/runtime-tests/src/test/scala/cats/effect/TracingTests.scala @@ -16,6 +16,7 @@ package cats.effect +import cats.implicits._ import cats.effect.tracing.IOTrace import org.scalatest.funsuite.AsyncFunSuite import org.scalatest.matchers.should.Matchers @@ -41,4 +42,23 @@ class TracingTests extends AsyncFunSuite with Matchers { r.captured shouldBe 4 } } + + test("contextual exceptions are not augmented more than once") { + val task = for { + _ <- IO.pure(1) + _ <- IO.pure(2) + _ <- IO.pure(3) + _ <- IO.shift(executionContext) + _ <- IO.pure(1) + _ <- IO.pure(2) + _ <- IO.pure(3) + e1 <- IO.raiseError(new Throwable("Encountered an error")).attempt + e2 <- IO.pure(e1).rethrow.attempt + } yield (e1, e2) + + for (r <- task.unsafeToFuture()) yield { + val (e1, e2) = r + e1.swap.toOption.get.getStackTrace.length shouldBe e2.swap.toOption.get.getStackTrace.length + } + } } diff --git a/site/src/main/mdoc/tracing/index.md b/site/src/main/mdoc/tracing/index.md index cbfa5045b3..942a21b72f 100644 --- a/site/src/main/mdoc/tracing/index.md +++ b/site/src/main/mdoc/tracing/index.md @@ -59,7 +59,7 @@ fiber. combinator was actually called by user code. For example, `void` and `as` are combinators that are derived from `map`, and should appear in the fiber trace rather than `map`. -3. **Contextual exceptions**. Exceptions captured by the `IO` runtime can be +3. **Enhanced exceptions**. Exceptions captured by the `IO` runtime can be augmented with async stack traces to produce more relevant stack traces. 4. Intermediate values. The intermediate values that an `IO` program encounters can be converted to a string to render. This can aid in understanding the @@ -170,7 +170,7 @@ def program: IO[Unit] = Keep in mind that the scope and amount of information that traces hold will change over time as additional fiber tracing features are merged into master. -## Contextual exceptions +## Enhanced exceptions The stack trace of an exception caught by the IO runloop looks similar to the following output: ``` @@ -216,7 +216,7 @@ is preserved, but all IO-related stack frames are replaced with async stack trace frames. This feature is controlled by the system property -`cats.effect.contextualExceptions`. It is enabled by default. +`cats.effect.enhancedExceptions`. It is enabled by default. ``` -Dcats.effect.stackTracingMode=false From dd2f6057c640a3291ca31cef6b7fdce13278f7ba Mon Sep 17 00:00:00 2001 From: Raas Ahsan Date: Fri, 14 Aug 2020 00:09:57 -0500 Subject: [PATCH 6/6] IOContext null check --- .../src/main/scala/cats/effect/internals/IORunLoop.scala | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala index c366a4a73f..a65b439f41 100644 --- a/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala +++ b/core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala @@ -114,7 +114,7 @@ private[effect] object IORunLoop { catch { case NonFatal(ex) => RaiseError(ex) } case RaiseError(ex) => - if (isStackTracing && enhancedExceptions) { + if (isStackTracing && enhancedExceptions && ctx != null) { augmentException(ex, ctx) } findErrorHandler(bFirst, bRest) match { @@ -247,7 +247,7 @@ private[effect] object IORunLoop { } catch { case NonFatal(ex) => RaiseError(ex) } case RaiseError(ex) => - if (isStackTracing && enhancedExceptions) { + if (isStackTracing && enhancedExceptions && ctx != null) { augmentException(ex, ctx) } findErrorHandler(bFirst, bRest) match {