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..b4ba1f8f62 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 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 099598e12b..8d6736686f 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,16 @@ public final class TracingPlatform { return Optional.empty(); } }) - .orElse(128); + .orElse(16); + + /** + * 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 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 cdfbc129c5..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,4 +38,7 @@ final private[effect] class IOContext() { def trace(): IOTrace = IOTrace(events.toList, captured, omitted) + 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 582cf439dd..a65b439f41 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.{enhancedExceptions, isStackTracing} import scala.util.control.NonFatal @@ -114,6 +114,9 @@ private[effect] object IORunLoop { catch { case NonFatal(ex) => RaiseError(ex) } case RaiseError(ex) => + if (isStackTracing && enhancedExceptions && ctx != null) { + augmentException(ex, ctx) + } findErrorHandler(bFirst, bRest) match { case null => cb(Left(ex)) @@ -244,6 +247,9 @@ private[effect] object IORunLoop { } catch { case NonFatal(ex) => RaiseError(ex) } case RaiseError(ex) => + if (isStackTracing && enhancedExceptions && ctx != null) { + augmentException(ex, ctx) + } findErrorHandler(bFirst, bRest) match { case null => return currentIO.asInstanceOf[IO[A]] @@ -357,6 +363,43 @@ 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 stackTrace = ex.getStackTrace + if (!stackTrace.isEmpty) { + 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 93b1e094f6..2b6efcdd5e 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(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 86cffde5d3..5c2c525cce 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\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,13 +62,16 @@ final case class IOTrace(events: List[IOEvent], captured: Int, omitted: Int) { } .mkString("\n") - header + body + val acc2 = if (omitted > 0) { + "\n" + TurnRight + s" ... ($omitted frames omitted)\n" + } else "\n" + TurnRight + "\n" + + acc0 + acc1 + acc2 } else { - val acc0 = s"IOTrace: $captured frames captured, $omitted omitted\n" 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) @@ -76,42 +79,27 @@ 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" } } } 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 { @@ -121,9 +109,25 @@ private[effect] object IOTrace { case (_, callSite) => !stackTraceFilter.exists(callSite.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." + ) } 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 99f6e6ab08..942a21b72f 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. **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 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. +## Enhanced 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.enhancedExceptions`. It is enabled by default. + +``` +-Dcats.effect.stackTracingMode=false +``` + ### Complete example Here is a sample program that demonstrates tracing in action.