Add support for tracing methods asynchronously #86

HaloFour · 2018-03-09T15:42:55Z

Adds support for tracing methods that return objects indicating asynchronous completion of a given task. The span itself remains open until the task is completed as determined by an implementation of AsyncTraceService that can support the return type of the method and register for completion. The duration of the method execution itself is logged via a timer on the span.

This PR includes support for Scala's Future[T] trait.

codecov-io · 2018-03-09T15:48:21Z

Codecov Report

Merging #86 into master will decrease coverage by 0.13%.
The diff coverage is 90.56%.

@@            Coverage Diff             @@
##           master      #86      +/-   ##
==========================================
- Coverage   90.98%   90.85%   -0.14%     
==========================================
  Files          30       35       +5     
  Lines         599      645      +46     
  Branches       75       76       +1     
==========================================
+ Hits          545      586      +41     
- Misses         54       59       +5

Impacted Files	Coverage Δ
...ey/core/async/ScalaFutureNotificationHandler.scala	`100% <100%> (ø)`
.../src/main/scala/com/comcast/money/core/Money.scala	`100% <100%> (ø)`	⬆️
.../scala/com/comcast/money/aspectj/TraceAspect.scala	`100% <100%> (ø)`	⬆️
...a/com/comcast/money/core/async/AsyncNotifier.scala	`100% <100%> (ø)`
...y/core/async/AsyncNotificationHandlerFactory.scala	`100% <100%> (ø)`
...cast/money/core/async/DirectExecutionContext.scala	`33.33% <33.33%> (ø)`
...scala/com/comcast/money/aspectj/FutureAspect.scala	`81.25% <81.25%> (ø)`
... and 2 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update c5d087d...943197d. Read the comment docs.

pauljamescleary · 2018-03-09T16:42:55Z

money-aspectj/src/test/scala/com/comcast/money/aspectj/TraceAspectSpec.scala

@@ -76,6 +79,12 @@ class TraceAspectSpec extends WordSpec
    throw new RuntimeException("not-ignored")
  }

+  @Traced(


As opposed to adding an async flag, with aspectj anyway we can add a different joinpoint / pointcut on functions with annotations @Trace that return a promise (I think). Have you tried that? Unsure off the top of my head if that would work

That would probably work although might require some effort to avoid ambiguity with existing pointcut. The problem with that is that it locks it to supporting only specific types and there is a fairly wide ecosystem of these types out there since Java didn't add one offering a callback until Java 8. Promise[T] is quite specific to Scala and its uncommon to see in other Java libraries.

Right, I am unclear if it would work. Can we have a test where, if someone sets async to be true, on something that is not async, that everything still works?

Imagine

@Traced(value="sync", async=true) def plusOne(x: Int): Int = x + 1

Agreed, the tests are a little anemic right now. This PR is more a spike for the purpose of discussion.

I might need to approach the unit tests a little differently as they should validate that log records aren't written until the promise/future is complete and the current helper methods don't really lend themselves to that, short of waiting for a timeout to expire. I'm thinking of mocking the Tracer instead.

The main test that I would like to try out is nested futures (futures with flatmaps).

When I worked with scala Futures in the past, the onComplete of a future was executed in odd ways.

Imagine you have 3 levels of functions / nested futures via flatmaps and maps. You create child spans at each level, so 3 levels deep in a span tree. The onComplete and context that was passed was "off".

Sorry I don't have more information, I have to check out your PR and try and re-create the issue I saw

Also, I think your example is odd. Seems like you have a future that yields a future as a value. That doesn't seem like a valid use case. I am curious if some of the contrived tests I wrote are things that people would never write?

Certainly .flatMap { x => Future { x + 1 } } is valid

But Future { Future { x } } is not

Which example is that? I'm trying to duplicate (or at least reinterpret) the unit tests you had around traced futures. Some of the examples are contrived intentionally but I also wouldn't discount my flubbing things up. I've not had the luxury of dedicating my attention to this recently.

I was playing with going down a path of having TraceAspect replace the existing Span with a wrapper AsyncSpan which internally would use an AtomicInteger as a reference counter. Invoking a terminal method on Future like onComplete would bump that counter up. When that callback would complete it would call stop, which would decrease the counter, as would when the instrumented future completed. Only when the counter reached zero would the span actually be stopped. I don't think that's quite what you were talking about, though.

That’s a great idea!

I was thinking that perhaps my old TraceAspect unit tests had test cases that were invalid.

…ases

pauljamescleary · 2018-03-14T20:31:17Z

money-core/src/main/scala/com/comcast/money/core/async/AsyncTracingService.scala

@@ -24,7 +24,7 @@ object AsyncTracingService {
  private lazy val services = loadServices()

  def findTracingService(future: AnyRef): Option[AsyncTracingService] =
-    services.find(_.supports(future))
+    if (future != null) services.find(_.supports(future)) else None


nitpicky, but...

Option(future).map(f => services.find(_.supports(f))

nitpicky back at you, but: 😁

Option(future).flatMap(f => services.find(_.supports(f))

HaloFour · 2018-03-14T20:32:39Z

I've reworked the asynchronous tracing aspect so that it behaves a bit differently.

Two spans are created instead of one. The first span represents the synchronous execution of the method. The second span, which is a child of the first span, represents the asynchronous operation represents by the future returned from the method. The second span is popped from the stack of spans and is left open after the method returns. When the future is complete, that triggers the second span to be closed based on the result of the future.

That second span is never closed if the following situations happen:

The method returns null.
The method returns something that isn't recognized to be a future
The method throws an exception

The success of the second span depends on the success of the future and respects the same ignored exceptions.

Given that the second asynchronous span is popped from the SpanLocal would there be any negative consequences from never stopping it?

HaloFour · 2018-03-14T20:37:20Z

I'll also note that I don't particularly care for the name AsyncTracingService, but I haven't thought of a good alternative. I didn't want to waste too much time on it and I'm open to suggestions.

pauljamescleary · 2018-03-14T20:42:58Z

money-aspectj/src/main/scala/com/comcast/money/aspectj/TraceAspect.scala

+
+  private def traceMethodAsync(joinPoint: ProceedingJoinPoint, traceAnnotation: Traced): AnyRef = {
+    val key = traceAnnotation.value()
+    val asyncKey = key + "-async"


why do we append -async to the name?

I'm creating two spans. I'm giving the second span which represents the async task the suffix -async. I could change that to do something else, or make it configurable.

Ok, that is where I was confused. I don't understand why we need two separate spans.

We use Money heavily with scala futures, and all tracing is declaritive in the code. We want to give the user the ability to start / stop however we want.

It is a little unclear here with the @Traced annotation as to when the span actually starts. The way we have done this is that the span starts when the method is invoked and completes when the Future (Promise) ends. Something conceptually like this...

def doSomethingTraced(foo: String): Future[String] = { val span = startSpan("myName") val fut = doSomethingInTheFuture(foo) fut.onComplete { case Success(x) => span.stop(true); case Failure(e) => span.stop(false) } }

I see. That is the approach I was taking in the first iteration and I have no problem going back to that model. If I do that then the code above could be reduced to:

@Traced(value = "myName", async = true) def doSomethingTraced(foo: String): Future[String] = doSomethingInTheFuture(foo)

…fter the method is invoked until the future is complete

HaloFour · 2018-03-15T12:21:50Z

Okie dokie, I've reverted the logic back to the previous implementation, where a single span is created prior to the annotated method being called and that span not being stopped if the method returns a recognized future that is not yet complete. I've updated all of the unit tests to also reflect this change.

pauljamescleary · 2018-03-20T09:42:36Z

Thumbing this up. Thanks for the contribution!!!

Let me know if there are any other pending modifications to this, and if I can merge this before your other PR.

HaloFour · 2018-03-20T13:40:51Z

Great. I am sitting on a couple of additional unit tests but no modification to the current functionality.

I was toying with the idea of switching from using the Java ServiceLoader to instead using the same typesafe Config mechanism that Money uses for handlers and other configuration. I reached for ServiceLoader since I was more familiar with it coming from Jersey and it's frequently used for pluggable connectors like this but I'd want it to fit in with the established paradigm used by Money. Kris didn't have an opinion either way.

pauljamescleary · 2018-03-21T21:22:35Z

Good to merge @HaloFour ?

ptravers · 2018-03-22T20:31:05Z

money-aspectj/src/test/scala/com/comcast/money/aspectj/TraceAspectSpec.scala

+
+        When("the method is invoked")
+        val promise = Promise[String]()
+        val future = asyncMethodWithIgnoredException(promise)


should future maybe be promise. I feel like I'm being lied to

HaloFour · 2018-03-22T20:35:59Z

Refactored to using typesafe Config to load the AsyncNotificationHandler instances (and changed their name to fit better with SpanHandler). Refactoring some bits to be more idiomatic Scala (with some help from @ptravers who knows Scala much better than I).

Open questions:

The AsyncNotificationHandler returns a value of AnyRef. This is to allow the handler to replace the return value with another compatible return value, just in case we'd want our tracing callback to happen before other registered callbacks. This does complicate the implementation and may not be that important.
I have implemented my own ExecutionContext which invokes the callback on the current thread. While this is generally frowned upon the thought is that the callback to finish tracing should be very fast and it would be a waste of resources and could potentially bloat the span times to put that back onto the global ExecutionContext. I expose the ExecutionContext parameter through the AsyncNotificationHandler trait, which is probably a bit overkill, and I could probably isolate that to just the ScalaFutureNotificationHandler class instead.

ptravers · 2018-03-22T20:38:46Z

money-core/src/main/scala/com/comcast/money/core/async/AsyncNotificationHandlerFactory.scala

+
+object AsyncNotificationHandlerFactory {
+
+  def create(config: Config): AsyncNotificationHandler = {


What about object AsyncNotificationHandler and create as apply would that look bad at call site? I guess this way you can just import AsyncNotificationHandlerFactory.create

ptravers · 2018-03-22T20:43:28Z

money-core/src/test/scala/com/comcast/money/core/SpecHelpers.scala


-  def add(log: String, message: String) = messages.addBinding(log, message)
+  def add(log: String, message: String): Unit = {


I kind of like it better without the brackets but...

HaloFour · 2018-03-22T23:57:42Z

I ended up removing the ExecutionContext parameter. All it really did was add a lot of noise and the interface would only really make sense in Scala-specific contexts. I still use the DirectExecutionContext directly within ScalaFutureNotificationHandler to keep the span callback on the same thread.

HaloFour · 2018-03-23T00:22:11Z

Unless there are further comments regarding implementation or style I believe that this should be ready to merge.

…TraceAspect

HaloFour · 2018-03-23T00:59:23Z

Okay, I lied. The complexity of TraceAspect#adviseMethodsWithTracing bothered me so I refactored the async portion out into a helper method with lots of comments and I refactored a bit of the method itself to hopefully be a little more clear.

Now I think I'm good to merge this PR. 😀

HaloFour · 2018-04-11T22:16:44Z

I've commited the FutureAspect and converted tests. Most of them pass but a few are kind of flaky and I'm still looking into the reason why.

There are three tests which fail regularly and I don't have a good answer for them. They rely on terminal/non-composed methods on Future[T] which create an inherent race condition between their execution and the span being stopped due to the future being completed. To my knowledge there is no prescribed order in which the registered callbacks of a future are executed and those callbacks are subsequently submitted to an execution context which makes the order of operations even more nondeterministic. I'll keep poking at ideas but I have a feeling that such operations wouldn't really compose well into a span.

The methods in question are:

onComplete
onSuccess
onFailure
foreach

HaloFour · 2018-04-19T15:18:01Z

I wonder if you would be amenable to breaking this into separate PRs. I see two orthogonal concerns here:

Support the tracing of methods that return a value representing a "future" where the span remains open until that "future" is complete.
Support "capturing" and "continuing" the current Span on the callbacks registered to a particular "future" so that whatever they trace can be correlated together.

The former I think is pretty cut and dry.

The latter gets into the weeds of implementation details around each implementation of "future", as we're seeing with scala.concurrent.Future. We'd probably run into the same kinds of problems trying to extend that support to java.util.concurrent.CompletionStage, com.google.common.util.concurrent.ListenableFuture, rx.Observable or any of the other potential libraries that exist out there.

pauljamescleary · 2018-04-19T23:11:44Z

I think that cutting this up makes sense.

HaloFour · 2018-04-20T00:09:50Z

I've reset this branch back to the commit prior to diving into the Future rabbit hole. If a method returns a Future and is annotated with @Traced(value = "whatever", async = true) then the Span will not be closed until after that Future is completed. Additional handlers can be configured to support other future types also, like java.util.concurrency.CompletionStage.

Speaking of, I'd love to make that a module of this project but it looks like Money currently targets Java 6. Is that to retain compatibility with older projects or would it be possible to bump the version up to 8?

Add support for tracing methods asynchronously

d4aaf6e

HaloFour mentioned this pull request Mar 9, 2018

Discussion: Asynchronous Tracing #85

Open

pauljamescleary reviewed Mar 9, 2018

View reviewed changes

Change async tracing strategy, expand unit tests to cover many more c…

d5f71c7

…ases

pauljamescleary reviewed Mar 14, 2018

View reviewed changes

PR feedback

d2435e7

pauljamescleary reviewed Mar 14, 2018

View reviewed changes

Revert to tracing a single span for async methods that remains open a…

c00cb5a

…fter the method is invoked until the future is complete

Refactoring and additional unit tests

eb4c4cc

pauljamescleary approved these changes Mar 20, 2018

View reviewed changes

HaloFour added 2 commits March 22, 2018 15:36

Some refactoring/renaming, convert from ServiceLoader to typesafe Config

126b77c

More refactoring, cleanup

da4c4d0

ptravers reviewed Mar 22, 2018

View reviewed changes

HaloFour added 2 commits March 22, 2018 18:18

Address comments

68a7245

Removing ExecutionContext parameter from trait

f217beb

Minor refactoring and comments to help clarify the async behavior in …

943197d

…TraceAspect

HaloFour mentioned this pull request Mar 31, 2018

Add tracing support for Apache HttpAsyncClient #84

Open

HaloFour force-pushed the async-tracing branch from ed8045d to 943197d Compare April 20, 2018 00:04

kristomasette merged commit 13d9c86 into Comcast:master Apr 20, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add support for tracing methods asynchronously #86

Add support for tracing methods asynchronously #86

HaloFour commented Mar 9, 2018

codecov-io commented Mar 9, 2018 •

edited

Loading

pauljamescleary Mar 9, 2018

HaloFour Mar 9, 2018 •

edited

Loading

pauljamescleary Mar 10, 2018

HaloFour Mar 10, 2018

pauljamescleary Apr 3, 2018

pauljamescleary Apr 19, 2018 •

edited

Loading

HaloFour Apr 19, 2018

HaloFour Apr 19, 2018

pauljamescleary Apr 19, 2018

pauljamescleary Apr 19, 2018

pauljamescleary Mar 14, 2018

HaloFour Mar 14, 2018

HaloFour commented Mar 14, 2018

HaloFour commented Mar 14, 2018

pauljamescleary Mar 14, 2018

HaloFour Mar 14, 2018

pauljamescleary Mar 15, 2018

HaloFour Mar 15, 2018

HaloFour commented Mar 15, 2018

pauljamescleary commented Mar 20, 2018

HaloFour commented Mar 20, 2018

pauljamescleary commented Mar 21, 2018

ptravers Mar 22, 2018 •

edited

Loading

HaloFour commented Mar 22, 2018

ptravers Mar 22, 2018

ptravers Mar 22, 2018

HaloFour commented Mar 22, 2018

HaloFour commented Mar 23, 2018

HaloFour commented Mar 23, 2018

HaloFour commented Apr 11, 2018

HaloFour commented Apr 19, 2018

pauljamescleary commented Apr 19, 2018

HaloFour commented Apr 20, 2018


		object AsyncNotificationHandlerFactory {

		def create(config: Config): AsyncNotificationHandler = {


		def add(log: String, message: String) = messages.addBinding(log, message)
		def add(log: String, message: String): Unit = {

Add support for tracing methods asynchronously #86

Add support for tracing methods asynchronously #86

Conversation

HaloFour commented Mar 9, 2018

codecov-io commented Mar 9, 2018 • edited Loading

Codecov Report

Choose a reason for hiding this comment

HaloFour Mar 9, 2018 • 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

pauljamescleary Apr 19, 2018 • 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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

HaloFour commented Mar 14, 2018

HaloFour commented Mar 14, 2018

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

HaloFour commented Mar 15, 2018

pauljamescleary commented Mar 20, 2018

HaloFour commented Mar 20, 2018

pauljamescleary commented Mar 21, 2018

ptravers Mar 22, 2018 • edited Loading

Choose a reason for hiding this comment

HaloFour commented Mar 22, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

HaloFour commented Mar 22, 2018

HaloFour commented Mar 23, 2018

HaloFour commented Mar 23, 2018

HaloFour commented Apr 11, 2018

HaloFour commented Apr 19, 2018

pauljamescleary commented Apr 19, 2018

HaloFour commented Apr 20, 2018

codecov-io commented Mar 9, 2018 •

edited

Loading

HaloFour Mar 9, 2018 •

edited

Loading

pauljamescleary Apr 19, 2018 •

edited

Loading

ptravers Mar 22, 2018 •

edited

Loading