Enhanced exceptions #1077

RaasAhsan · 2020-08-12T04:18:39Z

With asynchronous stack tracing implemented, we have the ability to make exceptions caught by the IO runloop much more useful and relevant than they were before. This PR introduces enhanced exceptions, which is a feature that augments stack traces of caught exceptions with information from an accumulated fiber trace. The feature is controlled by a system property cats.effect.enhancedExceptions, which is enabled by default and also requires asynchronous stack tracing to be enabled.

Stack traces before:

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)

Stack traces after:

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)

The original idea for this feature called for a TracedException wrapper, but there were quite a few problems with that approach, one of which was deciding where to wrap exceptions.

Relevant Gitter discussion: https://gitter.im/typelevel/cats-effect-dev?at=5f31e511e20413052e7c556e

TODO:

All my review comments
Benchmarks
Should we sanitize the augmented stack traces like we do for printFiberTrace?

core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java

core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala

core/shared/src/main/scala/cats/effect/internals/RingBuffer.scala

RaasAhsan · 2020-08-12T04:21:22Z

core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala

@@ -121,9 +109,33 @@ private[effect] object IOTrace {
        case (_, callSite) => !stackTraceFilter.exists(callSite.getClassName.startsWith(_))
      }

+  def dropRunLoopSuffix(frames: List[StackTraceElement]): List[StackTraceElement] =


IOTrace companion object seems like a weird place to put this

Maybe it should be in IORunLoop, since it's technically part of the runloop's implementation details?

RaasAhsan · 2020-08-12T04:21:58Z

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"


I'm going to reorganize this code and come up with better names.

core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala

RaasAhsan · 2020-08-12T04:24:47Z

core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala

@@ -114,6 +114,9 @@ private[effect] object IORunLoop {
            catch { case NonFatal(ex) => RaiseError(ex) }

        case RaiseError(ex) =>
+          if (isStackTracing && contextualExceptions) {


I'm still thinking about if this is the correct place to do this.

I keep going back and forth. On one hand, doing it here means that every exception, even those explicitly raiseErrored and later attempted by users, gets decorated. This means that if users are doing something like handleErrorWith(log.error(_)), they'll see the augmented trace. This seems very valuable!

But conversely, this also means that we pay the penalty of rendering the trace every time we call raiseError, which is not a small performance hit I would assume. Maybe worth it? Probably? I'm not 100% sure.

I think we also have to be careful because augmented exceptions can be re-caught or re-lifted into the runloop. For example, IO.raiseError(ex).attempt.rethrow, so I think we might need to check if it's already been augmented. I'm hoping the benchmarks will paint a better picture, but worst case it's something users can disable.

joroKr21 · 2020-08-12T04:50:47Z

Brilliant 👍

joroKr21 · 2020-08-12T04:52:59Z

How would this interact with NoStackTrace?

RaasAhsan · 2020-08-12T05:17:56Z

@joroKr21 if NoStackTrace is mixed into a given Throwable, t.getStackTrace will be empty, so nothing will be added based on the current behavior. If it's more appropriate, we can change the implementation so the fiber trace that has been accumulated so far is included in the stack trace. That's worth discussing.

RaasAhsan · 2020-08-14T04:53:35Z

core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala

+  private def augmentException(ex: Throwable, ctx: IOContext): Unit = {
+    val stackTrace = ex.getStackTrace
+    if (!stackTrace.isEmpty) {
+      val augmented = stackTrace(stackTrace.length - 1) eq augmentationMarker


So the idea here is that a reference equality is probably a lot faster than substring searches. After we augment an exception, we append the augmentation marker which can be used for comparison later. Notice that because it is declared private, callers can't access it and therefore they can't accidentally insert a marker.

The consequence of this is that printed stack traces show the marker at the end. I verified that we can't insert null as a marker.

java.lang.Throwable: hello world! at org.simpleapp.examples.Main$.b(Main.scala:29) at org.simpleapp.examples.Main$.a(Main.scala:26) at org.simpleapp.examples.Main$.$anonfun$foo$11(Main.scala:39) at main$ @ org.simpleapp.examples.Main$.main(Main.scala:23) at map @ org.simpleapp.examples.Main$.$anonfun$foo$10(Main.scala:39) at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$8(Main.scala:37) at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$6(Main.scala:36) at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$4(Main.scala:35) at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$2(Main.scala:34) at flatMap @ org.simpleapp.examples.Main$.foo(Main.scala:33) at flatMap @ org.simpleapp.examples.Main$.program(Main.scala:44) at as @ org.simpleapp.examples.Main$.run(Main.scala:50) at main$ @ org.simpleapp.examples.Main$.main(Main.scala:23) at .(:0)

We're also doing a lot of Array and List manipulation here. Without thinking about it more, I'm not sure what the most efficient approach is (do everything in Array or List, and when should we convert back to an array?).

I'll benchmark this tomorrow so we have a concrete answer.

I just realized that users can access an instance of the market, through the stack trace itself! I don't think it'll be a problem either way because they would have to be deliberately manipulating stack traces for something to mess up. Same deal with checking @ probably.

So the idea here is that a reference equality is probably a lot faster than substring searches. After we augment an exception, we append the augmentation marker which can be used for comparison later. Notice that because it is declared private, callers can't access it and therefore they can't accidentally insert a marker.

Hmm, I think this is worth benchmarking. In my experience, indexOf is really really fast, so I don't think there'll be that much of a difference, but I could be mistaken!

RaasAhsan · 2020-08-14T05:11:33Z

core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala

+   * to include the async stack trace.
+   */
+  private def augmentException(ex: Throwable, ctx: IOContext): Unit = {
+    val stackTrace = ex.getStackTrace


We will throw a NPE here if ex is null. I think that would break existing code that happen to rely on this behavior

Do people actually run raiseError(null)? I think I'm pretty comfortable telling those people that they just have to turn off augmented exceptions, because they don't deserve nice things. :-P

RaasAhsan · 2020-08-15T06:00:33Z

Here is a benchmark comparison between the reference equality check, the indexOf check, cached tracing in master, and disabled tracing for reference.

indexOf
[info] Benchmark                     (size)   Mode  Cnt     Score    Error  Units
[info] AttemptBenchmark.errorRaised   10000  thrpt    5  1182.529 ± 14.167  ops/s
[info] AttemptBenchmark.happyPath     10000  thrpt    5  2222.477 ± 20.280  ops/s

reference equality
[info] Benchmark                     (size)   Mode  Cnt     Score    Error  Units
[info] AttemptBenchmark.errorRaised   10000  thrpt    5  1222.009 ±  4.819  ops/s
[info] AttemptBenchmark.happyPath     10000  thrpt    5  2165.725 ± 16.240  ops/s

cached tracing pre-enhanced exceptions
AttemptBenchmark.errorRaised | 1403.077
AttemptBenchmark.happyPath | 2120.155

disabled tracing
[info] Benchmark                     (size)   Mode  Cnt     Score    Error  Units
[info] AttemptBenchmark.errorRaised   10000  thrpt    5  2032.301 ± 17.058  ops/s
[info] AttemptBenchmark.happyPath     10000  thrpt    5  2313.851 ± 91.837  ops/s

The reference equality check is slightly faster, but not by any significant margin. Your call @djspiewak ! :D Also, I'm positive we can improve the performance of the Array and List operations more, but I'm not sure whether we should consider it a blocker for this PR.

djspiewak · 2020-08-16T02:17:02Z

The reference equality check is slightly faster, but not by any significant margin. Your call @djspiewak ! :D Also, I'm positive we can improve the performance of the Array and List operations more, but I'm not sure whether we should consider it a blocker for this PR.

:-) Let's go with indexOf since it doesn't affect the user-visible output. I definitely think we can optimize this further, though it's worth keeping in mind that the errorRaised benchmark is a bit artificial. Let's land this and refine in follow-ups!

Raas Ahsan added 4 commits August 11, 2020 02:18

stack trace manipulation

969559f

reverse printFiberTrace order

e032a7b

configuration and augmentException

be33127

Documentation

ccedb18

RaasAhsan commented Aug 12, 2020

View reviewed changes

RaasAhsan changed the title ~~Contextual exceptions~~ Enhanced exceptions Aug 14, 2020

address pr feedback

a7a0e4e

RaasAhsan commented Aug 14, 2020

View reviewed changes

IOContext null check

dd2f605

RaasAhsan commented Aug 14, 2020

View reviewed changes

djspiewak merged commit 0fdde92 into typelevel:series/2.x Aug 16, 2020

This was referenced Aug 16, 2020

Improve performance of enhanced exceptions #1090

Closed

Use indexOf for enhanced exceptions #1091

Merged

Avasil mentioned this pull request Sep 13, 2020

Implement Asynchronous Stack Traces for Task monix/monix#1267

Merged

6 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Enhanced exceptions #1077

Enhanced exceptions #1077

RaasAhsan commented Aug 12, 2020 •

edited

Loading

RaasAhsan Aug 12, 2020

djspiewak Aug 12, 2020

RaasAhsan Aug 12, 2020

RaasAhsan Aug 12, 2020

djspiewak Aug 12, 2020

RaasAhsan Aug 12, 2020 •

edited

Loading

joroKr21 commented Aug 12, 2020

joroKr21 commented Aug 12, 2020

RaasAhsan commented Aug 12, 2020 •

edited

Loading

RaasAhsan Aug 14, 2020 •

edited

Loading

RaasAhsan Aug 14, 2020

djspiewak Aug 14, 2020

RaasAhsan Aug 14, 2020

djspiewak Aug 14, 2020 •

edited

Loading

RaasAhsan commented Aug 15, 2020 •

edited

Loading

djspiewak commented Aug 16, 2020

Enhanced exceptions #1077

Enhanced exceptions #1077

Conversation

RaasAhsan commented Aug 12, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

RaasAhsan Aug 12, 2020 • edited Loading

Choose a reason for hiding this comment

joroKr21 commented Aug 12, 2020

joroKr21 commented Aug 12, 2020

RaasAhsan commented Aug 12, 2020 • edited Loading

RaasAhsan Aug 14, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

djspiewak Aug 14, 2020 • edited Loading

Choose a reason for hiding this comment

RaasAhsan commented Aug 15, 2020 • edited Loading

djspiewak commented Aug 16, 2020

RaasAhsan commented Aug 12, 2020 •

edited

Loading

RaasAhsan Aug 12, 2020 •

edited

Loading

RaasAhsan commented Aug 12, 2020 •

edited

Loading

RaasAhsan Aug 14, 2020 •

edited

Loading

djspiewak Aug 14, 2020 •

edited

Loading

RaasAhsan commented Aug 15, 2020 •

edited

Loading