If you’ve ever tried to debug asynchronous code written with Twitter Future
s,
you may have found that the stack trace isn’t always helpful. The stack trace
at a given point in the program includes the active stack frames and thus shows
the chain of function calls that led up to that point. Since asynchronous
execution causes different parts of a program to have their stack traces chopped
up, the stack trace often shows unexpected internal library calls and is missing
the causality developers are used to from synchronous code. As a result, the
context leading to the current stack frame is lost.
IntelliJ 2017.1 included a feature called Capture Points. This feature lets us stitch together stack frames so that the order of functions in the stack trace respects the order in which they were called.
Our summer intern, Haggai Kaunda, wrote capture
points specific to Twitter Future
s
(thanks, Haggai!). Using these can make debugging asynchronous code written
with Twitter Future
s simpler by providing more informative stack traces.
Note that as of November 2017, the capture points are guaranteed to work with only Scala 2.11. We are not working on capture points for 2.12 at this time; if you would like to help make this feature available for more users, you can submit a pull request on util’s GitHub repo.
To start using, you can grab the capture points XML file directly from GitHub, and after our next release it will be available as an artifact published to Maven Central.
The capture points are defined in TwitterFuturesCapturePoints.xml. To import them into IntelliJ,
Set a breakpoint where you wish to see the stack trace, debug your code, and look at the “Frames” tab in the Debugger. Any asynchronous calls in the stack trace will appear in logical order. If you wish to clean up the stack trace, click the funnel icon in the top right, “Hide Frames from Libraries”.
We will illustrate how to use the capture points to assist with debugging with a small example written by Kevin Oliver (thanks, Kevin!).
A brief explanation of this test: the test passes a Promise[Int]
through three methods and then sets the Promise
’s value in a futurePool
.
The calls are asynchronous, but the logical flow of the test is as follows:
test
block calls someBusinessLogic
someBusinessLogic
calls moreBusinessLogic
moreBusinessLogic
calls lordBusinessLogic
lordBusinessLogic
waits for the Promise
’s value to be setPromise
’s value is set in the test block (this could happen at any
time; it is not necessarily step number 5)lordBusinessLogic
returnstest
’s result
variable is 4
, and the test passesSuppose we wish to inspect the stack trace from inside lordBusinessLogic
. If
we set a breakpoint at line 47 and then debug the test in IntelliJ with the
capture points disabled, we see the following stack trace:
apply$mcVI$sp:47, Demo$$anonfun$lordBusinessLogic$1
apply:1820, Future$$anonfun$onSuccess$1
apply:205, Promise$Monitored
run:532, Promise$$anon$7
run:198, LocalScheduler$Activation
submit:157, LocalScheduler$Activation
submit:274, LocalScheduler
submit:109, Scheduler$
runq:522, Promise
updatelfEmpty:880, Promise
update:859, Promise
setValue:835, Promise
apply$mcV$sp:20, Demo$$anonfun$3$$anonfun$apply$1
apply:15, Try$
run:140, ExecutorServiceFuturePool$$anon$4
The library calls in the stack trace do not help us understand our code. If we enable the capture points and again debug the test, we see the following stack trace:
apply$mcVI$sp:47, Demo$$anonfun$lordBusinessLogic$1
apply:1820, Future$$anonfun$onSuccess$1
onSuccess:1819, Future
lordBusinessLogic:42, Demo
moreBusinessLogic:38, Demo
someBusinessLogic:31, Demo
apply:17, Demo$$anonfun$3
This is much cleaner and it includes only calls to functions we wrote. It lets
us clearly see that the test block called someBusinessLogic
, that
someBusinessLogic
called moreBusinessLogic
, and that moreBusinessLogic
called lordBusinessLogic
.
Please let us know if you have any questions via @finagle, the Finaglers mailing list, or chat.
Happy debugging!