Can byteman be used to automatically wrap executors?

[ribrewguy]

This is a bit of a sprawling question, but wrapping all executors in a TracedExecutorService is quite intrusive. Is there a means to have byteman recognize an applicable situation and wrap the call?

[objectiser]

One approach would be to use a condition that checks IF getTracer().activeSpan() != null ?

[ribrewguy]

Thanks! I'm asking more about the entire call. Would something like this work:

RULE Wrap executor services
CLASS java.util.concurrent.Executors
METHOD newSingleThreadExecutor
HELPER io.opentracing.contrib.agent.OpenTracingHelper
AT EXIT
IF getTracer().activeSpan() != null
DO return new io.opentracing.contrib.concurrent.TracedExecutorService($0, getTracer())
ENDRULE

[objectiser]

Yes this should be possible, except the DO entry would be something like:

DO $! = new io.opentracing.contrib.concurrent.TracedExecutorService($!, getTracer())

I believe.

[pavolloffay]

I think this belongs to the ot-agent repo.

[ribrewguy]

Thanks! I'm working on testing this out. On a related note, is there any recommendation on how to handle completable futures? I know I can easily instrument a method that creates a CompletableFuture, but I want to instrument the get on the future, but only futures from specific methods.

[ribrewguy]

Testing indicates that either I still don't understand nested spans, or the active parent span context is not propagated. I setup a testbed based on some prod code that retrieved the tracer, created a parent span, within that span used an executor that submitted a Runnable that contained a byteman instrumented span.

pseudo:

        Tracer tracer = TracerResolver.resolveTracer();
        ExecutorService service = Executors.newSingleThreadExecutor();
        Logger log = LoggerFactory.getLogger(this.getClass());
        ActiveSpan span = tracer.buildSpan("testing executor wrapper").startActive();
        log.info("Service class: {}", service.getClass());
        try {
            service.submit(() -> {
                log.info("testing ledger span");
                getDao().latest(10);
            }).get();
        }
        catch (InterruptedException | ExecutionException e) {
            // TODO Auto-generated catch block
            e.printStackTrace();
        }
        span.deactivate();

The getDao.latest invocation had been tested in isolation to have been identified and traced properly using byteman.

Initially I used the following rule;

RULE Wrap executor services
CLASS java.util.concurrent.Executors
METHOD newSingleThreadExecutor
HELPER io.opentracing.contrib.agent.OpenTracingHelper
AT EXIT
IF getTracer().activeSpan() != null
DO $! = new io.opentracing.contrib.concurrent.TracedExecutorService($!, getTracer())
ENDRULE

Upon testing the logging for the service class was showing as a standard java executor. I then removed the conditional IF based on an active span from the rule and the opentracing wrapper class was printing as expected. This was unexpected since I definitely created an active parent span. It seems as if the rule did not recognize the code-created active span.

That's not where the unexpected behavior ended. Within the executor's runnable, the getDao.query call, which definitely works in isolation, did not trace at all.

Any thoughts?

[objectiser]

First thing to try would be moving the ActiveSpan span = tracer.buildSpan("testing executor wrapper").startActive(); before the ExecutorService service = Executors.newSingleThreadExecutor();. The active span must be started before calling the newSingleThreadExecutor as this is the condition being checked in the rule for that method.

[ribrewguy]

Good point. I adjusted the code as you described and replaced the byteman instrumented nested call with a manual span:

        ActiveSpan span = tracer.buildSpan("testing executor wrapper").startActive();
        ExecutorService service = Executors.newSingleThreadExecutor();
        Logger log = LoggerFactory.getLogger(this.getClass());
        log.info("Service class: {}", service.getClass());
        try {
            service.submit(() -> {
                log.info("testing ledger span");
                Tracer nestedTracer = TracerResolver.resolveTracer();
                ActiveSpan nestedSpan = nestedTracer.buildSpan("testing exec nested span").startActive();
                try {
                    Thread.sleep(5000L);
                }
                catch (InterruptedException e) {
                    // TODO Auto-generated catch block
                    e.printStackTrace();
                }
                nestedSpan.deactivate();
            }).get();
        }
        catch (InterruptedException | ExecutionException e) {
            // TODO Auto-generated catch block
            e.printStackTrace();
        }
        span.deactivate();

This kinda worked but the spans were recorded separately, not nested. I removed the byteman rule for executors and replaced the byteman wrapped executor with an explicit wrapped executor:

ExecutorService service = new TracedExecutorService(Executors.newSingleThreadExecutor(), tracer);

This also showed two different spans rather than nesting them. It seems as if the context is not propagated.

[objectiser]

You need to use the same Tracer instance - ideally registered with the GlobalTracer, as I believe they each manage their own active spans.

…

On Fri, Sep 22, 2017 at 2:16 PM, Todd ***@***.***> wrote: Good point. I adjusted the code as you described and replaced the byteman instrumented nested call with a manual span: ActiveSpan span = tracer.buildSpan("testing executor wrapper").startActive(); ExecutorService service = Executors.newSingleThreadExecutor(); Logger log = LoggerFactory.getLogger(this.getClass()); log.info("Service class: {}", service.getClass()); try { service.submit(() -> { log.info("testing ledger span"); Tracer nestedTracer = TracerResolver.resolveTracer(); ActiveSpan nestedSpan = nestedTracer.buildSpan("testing exec nested span").startActive(); try { Thread.sleep(5000L); } catch (InterruptedException e) { // TODO Auto-generated catch block e.printStackTrace(); } nestedSpan.deactivate(); }).get(); } catch (InterruptedException | ExecutionException e) { // TODO Auto-generated catch block e.printStackTrace(); } span.deactivate(); This kinda worked but the spans were recorded separately, not nested. I removed the byteman rule for executors and replaced the byteman wrapped executor with an explicit wrapped executor: ExecutorService service = new TracedExecutorService(Executors.newSingleThreadExecutor(), tracer); This also showed two different spans rather than nesting them. It seems as if the context is not propagated. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#7 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAKC0jlB8dGBHoTVBfP0SOLzrvH9FS1Wks5sk7NKgaJpZM4PfgcV> .

[ribrewguy]

Using GlobalTracer.register results in IllegalStateException: There is already a current global Tracer registered. Not registering the tracer, but simply using GlobalTracer.get() results in separate spans, not nested spans. Very confusing.

[objectiser]

Ok looks like a reproducer would be useful to investigate further.

[ribrewguy]

That's tricky since my setup is a little complex for a reproducer. However, I was able to get around this issue by altering the GlobalTracer. I have it initialize itself with the TracerResolver.resolveTracer() and if that's null it uses the noop. This is nice because I can be sure that calls to get will give me something useful and ensure that all callers to get will retrieve the same tracer. I'll submit a patch presently.

[ribrewguy]

After reviewing the current opentracing structure it seems as tho a patch to the current libraries isn't appropriate. This is because to do what I did in my custom class, I'd have to create a dependency on the traceresolver project which is currently a contrib project from within the opentracing-util project which is a higher-level project. That dependency direction seems incorrect. But this raises the question of why is this a contrib? It seems that an SPI-like approach of providing the implementation found on the classpath to the caller should be built in to the opentracing api itself. This is a common approach and would allow for things to "just work" with minimal effort.

If traceresolver was raised to a top level project or similar functionality was bundled into the api project then I imagine having GlobalTracer.get() use the resolver would be an appropriate and welcome addition.

[objectiser]

Its possible that this change may occur at some point - I think the idea was to get experience of using the TracerResolver in contrib first before considering it as part of the core API. But may be worth raising your specific scenario as an issue in the opentracing-java repo?

However, the agent does provide initialisation of the GlobalTracer based on the TracerResolver, so it may help solve the problem in your case? https://github.com/opentracing-contrib/java-agent/blob/master/opentracing-agent/src/main/java/io/opentracing/contrib/agent/OpenTracingHelper.java#L77