From bc20b957ed1ae300145e557f591b8d8d8aefed3e Mon Sep 17 00:00:00 2001 From: iamdanfox Date: Mon, 2 Sep 2019 11:10:02 +0100 Subject: [PATCH] tweaks to ckozak's DetachedSpan & demo usage (#247) --- .../com/palantir/tracing/TracingDemos.java | 177 +++++++++++------- .../tracing/TracingDemos/async_future.log | 43 ++--- .../backoffs_on_a_scheduled_executor.log | 13 +- .../TracingDemos/handles_async_spans.log | 73 ++++---- .../multi_producer_single_consumer.log | 102 ++++------ .../TracingDemos/transformed_future.log | 8 +- .../com/palantir/tracing/HtmlFormatter.java | 2 +- .../java/com/palantir/tracing/TimeBounds.java | 13 +- .../tracing/TestTracingExtensionDemo.java | 3 +- .../handles_async_spans.log | 53 +++--- .../{SpanToken.java => CloseableSpan.java} | 4 +- .../com/palantir/tracing/CloseableTracer.java | 2 + .../com/palantir/tracing/DetachedSpan.java | 49 +++-- .../java/com/palantir/tracing/Tracer.java | 32 ++-- .../java/com/palantir/tracing/TracerTest.java | 16 +- 15 files changed, 323 insertions(+), 267 deletions(-) rename tracing/src/main/java/com/palantir/tracing/{SpanToken.java => CloseableSpan.java} (89%) diff --git a/tracing-demos/src/test/java/com/palantir/tracing/TracingDemos.java b/tracing-demos/src/test/java/com/palantir/tracing/TracingDemos.java index c6286516e..f16c684a1 100644 --- a/tracing-demos/src/test/java/com/palantir/tracing/TracingDemos.java +++ b/tracing-demos/src/test/java/com/palantir/tracing/TracingDemos.java @@ -23,10 +23,10 @@ import com.google.common.util.concurrent.Futures; import com.google.common.util.concurrent.MoreExecutors; import com.google.common.util.concurrent.SettableFuture; +import java.util.concurrent.ArrayBlockingQueue; import java.util.concurrent.CountDownLatch; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; -import java.util.concurrent.PriorityBlockingQueue; import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.TimeUnit; import java.util.stream.IntStream; @@ -48,16 +48,17 @@ void handles_async_spans() throws Exception { ExecutorService executorService = Executors.newFixedThreadPool(numThreads); CountDownLatch countDownLatch = new CountDownLatch(numTasks); - try (CloseableTracer root = CloseableTracer.startSpan("root")) { - IntStream.range(0, numTasks).forEach(i -> { - // DetachedSpan detachedSpan = DetachedSpan.start("task-queue-time" + i); - executorService.submit(() -> { - // detachedSpan.close(); + IntStream.range(0, numTasks).forEach(i -> { + Tracer.clearCurrentTrace(); // just pretending all these tasks are on a fresh request + + DetachedSpan crossThread = DetachedSpan.start("task-queue-time" + i); + executorService.submit(() -> { + try (CloseableSpan t = crossThread.completeAndStartChild("task" + i)) { emit_nested_spans(); countDownLatch.countDown(); - }); + } }); - } + }); assertThat(countDownLatch.await(expectedDurationMillis + 1000, TimeUnit.MILLISECONDS)).isTrue(); } @@ -67,29 +68,42 @@ void handles_async_spans() throws Exception { void async_future() throws InterruptedException { int numThreads = 2; int numCallbacks = 10; - ExecutorService executorService = Tracers.wrap(Executors.newFixedThreadPool(numThreads)); + ExecutorService executorService = Executors.newFixedThreadPool(numThreads); final SettableFuture future = SettableFuture.create(); CountDownLatch latch = new CountDownLatch(numCallbacks); - IntStream.range(0, numCallbacks).forEach(i -> + try (CloseableTracer tracer = CloseableTracer.startSpan("I am a root span")) { + String traceId = Tracer.getTraceId(); + + IntStream.range(0, numCallbacks).forEach(i -> { + + DetachedSpan span = DetachedSpan.start("callback-pending" + i + " (cross thread span)"); + Futures.addCallback(future, new FutureCallback() { @Override public void onSuccess(@Nullable Object result) { - sleep(10, "success" + i); - latch.countDown(); + assertThat(Tracer.hasTraceId()).isFalse(); + try (CloseableSpan tracer = span.completeAndStartChild("success" + i)) { + assertThat(Tracer.getTraceId()).isEqualTo(traceId); + sleep(10); + latch.countDown(); + } } + @Override public void onFailure(Throwable throwable) { Assertions.fail(); } - }, executorService)); + }, executorService); + }); - executorService.submit(() -> { - try (CloseableTracer root = CloseableTracer.startSpan("root")) { - future.set(null); + try (CloseableTracer root = CloseableTracer.startSpan("bbb")) { + executorService.submit(() -> { + future.set(null); + }); } - }); + } assertThat(latch.await(10, TimeUnit.SECONDS)).isTrue(); } @@ -98,28 +112,42 @@ public void onFailure(Throwable throwable) { void multi_producer_single_consumer() throws InterruptedException { int numProducers = 2; int numElem = 20; - PriorityBlockingQueue work = new PriorityBlockingQueue<>(); + ArrayBlockingQueue work = new ArrayBlockingQueue(numElem); CountDownLatch submitLatch = new CountDownLatch(numElem); CountDownLatch consumeLatch = new CountDownLatch(numElem); - ExecutorService producerExecutorService = Tracers.wrap(Executors.newFixedThreadPool(numProducers)); - ExecutorService consumerExecutorService = Tracers.wrap(Executors.newFixedThreadPool(1)); + ExecutorService producerExecutorService = Executors.newFixedThreadPool(numProducers); + ExecutorService consumerExecutorService = Executors.newFixedThreadPool(1); try (CloseableTracer submit = CloseableTracer.startSpan("submit")) { IntStream.range(0, numElem).forEach(i -> { + + Tracer.clearCurrentTrace(); // just pretending all these tasks are on a fresh request + + DetachedSpan span = DetachedSpan.start("callback-pending" + i + " (cross thread span)"); producerExecutorService.submit(() -> { - try (CloseableTracer closeableTracer = CloseableTracer.startSpan("submit-work" + i)) { - work.add("work" + i); - submitLatch.countDown(); - } + work.add(new QueuedWork() { + @Override + public String name() { + return "work" + i; + } + + @Override + public DetachedSpan span() { + return span; + } + }); + submitLatch.countDown(); }); }); assertThat(submitLatch.await(10, TimeUnit.SECONDS)).isTrue(); consumerExecutorService.submit(() -> { for (int i = 0; i < numElem; i++) { - String poll = work.take(); - sleep(10, "processing" + poll); + QueuedWork queuedWork = work.take(); + try (CloseableSpan span = queuedWork.span().completeAndStartChild("consume" + queuedWork.name())) { + Thread.sleep(10); + } consumeLatch.countDown(); } return null; @@ -129,35 +157,30 @@ void multi_producer_single_consumer() throws InterruptedException { } @Test - @TestTracing(snapshot = true, layout = LayoutStrategy.SPLIT_BY_TRACE) + @TestTracing(snapshot = true, layout = LayoutStrategy.CHRONOLOGICAL) void backoffs_on_a_scheduled_executor() throws InterruptedException { ScheduledExecutorService executor = Tracers.wrap(Executors.newScheduledThreadPool(2)); CountDownLatch latch = new CountDownLatch(1); - try (CloseableTracer t = CloseableTracer.startSpan("some-request")) { - executor.execute(() -> { - // first attempt at a network call - sleep(100, "first attempt"); - - executor.schedule(() -> { - // attempt number 2 - sleep(100, "second attempt"); - - executor.schedule(() -> { - // attempt number 3 - sleep(100, "final attempt"); + DetachedSpan overall = DetachedSpan.start("overall request"); + executor.execute(() -> { - latch.countDown(); - }, 100, TimeUnit.MILLISECONDS); + try (CloseableTracer t = CloseableTracer.startSpan("first network call (pretending this fails)")) { + sleep(100); + } - sleep(200, "second tidying"); - }, 100, TimeUnit.MILLISECONDS); + DetachedSpan backoff = overall.childDetachedSpan("backoff"); + executor.schedule(() -> { + try (CloseableSpan attempt2 = backoff.completeAndStartChild("secondAttempt")) { + sleep(100); + overall.complete(); + latch.countDown(); - sleep(200, "first tidying"); - }); + } + }, 20, TimeUnit.MILLISECONDS); + }); - assertThat(latch.await(10, TimeUnit.SECONDS)).isTrue(); - } + assertThat(latch.await(10, TimeUnit.SECONDS)).isTrue(); MoreExecutors.shutdownAndAwaitTermination(executor, 1, TimeUnit.SECONDS); } @@ -167,54 +190,76 @@ void backoffs_on_a_scheduled_executor() throws InterruptedException { @SuppressWarnings("CheckReturnValue") void transformed_future() throws InterruptedException { SettableFuture future = SettableFuture.create(); - ScheduledExecutorService executor = Tracers.wrap(Executors.newScheduledThreadPool(2)); + ScheduledExecutorService executor = Executors.newScheduledThreadPool(2); CountDownLatch latch = new CountDownLatch(1); + DetachedSpan foo = DetachedSpan.start("foo"); FluentFuture.from(future) .transform(result -> { - sleep(100, "first"); - return result; + try (CloseableSpan t = foo.childSpan("first transform")) { + sleep(1000); + return result; + } }, executor) .transform(result -> { - sleep(100, "second"); - latch.countDown(); - return result; + try (CloseableSpan t = foo.childSpan("second transform")) { + sleep(1000); + latch.countDown(); + return result; + } + }, executor) + .addCallback(new FutureCallback() { + @Override + public void onSuccess(@Nullable Object result) { + foo.complete(); + } + + @Override + public void onFailure(Throwable throwable) { + foo.complete(); + } }, executor); executor.submit(() -> { - try (CloseableTracer root = CloseableTracer.startSpan("root")) { - future.set(null); - } + future.set(null); }); assertThat(latch.await(10, TimeUnit.SECONDS)).isTrue(); } - private static void sleep(int millis, String operation) { - try (CloseableTracer t = CloseableTracer.startSpan(operation)) { + private static void sleep(int millis) { + try { Thread.sleep(millis); } catch (InterruptedException e) { - throw new RuntimeException("dont care", e); + Thread.currentThread().interrupt(); + throw new RuntimeException(e); } } - private static void sleep(int millis) { - sleep(millis, "sleep " + millis); + private static void sleepSpan(int millis) { + try (CloseableTracer t = CloseableTracer.startSpan("sleep " + millis)) { + sleep(millis); + } } @SuppressWarnings("NestedTryDepth") private static void emit_nested_spans() { - try (CloseableTracer root = CloseableTracer.startSpan("root")) { + try (CloseableTracer root = CloseableTracer.startSpan("emit_nested_spans")) { try (CloseableTracer first = CloseableTracer.startSpan("first")) { - sleep(100); + sleepSpan(100); try (CloseableTracer nested = CloseableTracer.startSpan("nested")) { - sleep(90); + sleepSpan(90); } - sleep(10); + sleepSpan(10); } try (CloseableTracer second = CloseableTracer.startSpan("second")) { - sleep(100); + sleepSpan(100); } } } + + interface QueuedWork { + String name(); + DetachedSpan span(); + } } diff --git a/tracing-demos/src/test/resources/tracing/TracingDemos/async_future.log b/tracing-demos/src/test/resources/tracing/TracingDemos/async_future.log index 40a874b11..2619ca91b 100644 --- a/tracing-demos/src/test/resources/tracing/TracingDemos/async_future.log +++ b/tracing-demos/src/test/resources/tracing/TracingDemos/async_future.log @@ -1,21 +1,22 @@ -{"traceId":"d545f2dc62c95370","parentSpanId":null,"spanId":"d4a82ce1d0b7c9ae","operation":"root","startTimeMicroSeconds":1567084000551052,"durationNanoSeconds":2219562,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"bfa5123d9dec003d","spanId":"612ecc8ad2651fb9","operation":"success0","startTimeMicroSeconds":1567084000556032,"durationNanoSeconds":10312056,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"d4a82ce1d0b7c9ae","spanId":"bfa5123d9dec003d","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567084000553307,"durationNanoSeconds":13120623,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"82f85707b579ee10","spanId":"4bd643bc0d4f43df","operation":"success1","startTimeMicroSeconds":1567084000556055,"durationNanoSeconds":10419937,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"d4a82ce1d0b7c9ae","spanId":"82f85707b579ee10","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567084000553348,"durationNanoSeconds":13164323,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"fa9e58518f8d03ba","spanId":"718296e9bcb7d5e1","operation":"success3","startTimeMicroSeconds":1567084000566586,"durationNanoSeconds":10475697,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"d4a82ce1d0b7c9ae","spanId":"fa9e58518f8d03ba","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567084000566571,"durationNanoSeconds":10537431,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"9df0e0c69b32826a","spanId":"9721c786259e9dfd","operation":"success2","startTimeMicroSeconds":1567084000566535,"durationNanoSeconds":12526663,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"d4a82ce1d0b7c9ae","spanId":"9df0e0c69b32826a","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567084000566511,"durationNanoSeconds":12578626,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"54594d5512d0335a","spanId":"0f973e825b762b9d","operation":"success4","startTimeMicroSeconds":1567084000577193,"durationNanoSeconds":10065016,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"d4a82ce1d0b7c9ae","spanId":"54594d5512d0335a","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567084000577174,"durationNanoSeconds":10174865,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"d2c91d4295678b11","spanId":"9dc056e98c0fc872","operation":"success5","startTimeMicroSeconds":1567084000579178,"durationNanoSeconds":11540281,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"d4a82ce1d0b7c9ae","spanId":"d2c91d4295678b11","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567084000579161,"durationNanoSeconds":11778650,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"7d5172fa27973008","spanId":"156332e8dfadd9f0","operation":"success6","startTimeMicroSeconds":1567084000587452,"durationNanoSeconds":10290319,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"d4a82ce1d0b7c9ae","spanId":"7d5172fa27973008","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567084000587427,"durationNanoSeconds":10524029,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"2d417ddbd2e5b677","spanId":"b880d5f769ebac62","operation":"success7","startTimeMicroSeconds":1567084000591093,"durationNanoSeconds":12594213,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"d4a82ce1d0b7c9ae","spanId":"2d417ddbd2e5b677","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567084000591052,"durationNanoSeconds":12689004,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"2b64b3cd71712bd5","spanId":"08f475a3c82ee0a9","operation":"success8","startTimeMicroSeconds":1567084000598208,"durationNanoSeconds":10162597,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"d4a82ce1d0b7c9ae","spanId":"2b64b3cd71712bd5","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567084000598152,"durationNanoSeconds":10274988,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"985136e997c47f05","spanId":"3747cdce17335bea","operation":"success9","startTimeMicroSeconds":1567084000603883,"durationNanoSeconds":10218861,"metadata":{}} -{"traceId":"d545f2dc62c95370","parentSpanId":"d4a82ce1d0b7c9ae","spanId":"985136e997c47f05","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567084000603855,"durationNanoSeconds":10489810,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"49142deefcd1dd5f","spanId":"af3ddd010fd48254","operation":"bbb","startTimeMicroSeconds":1567179155782200,"durationNanoSeconds":529963,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":null,"spanId":"49142deefcd1dd5f","operation":"I am a root span","startTimeMicroSeconds":1567179155780579,"durationNanoSeconds":2218286,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"49142deefcd1dd5f","spanId":"580ff7b7ad4b95f3","operation":"callback-pending1 (cross thread span)","startTimeMicroSeconds":1567179155782089,"durationNanoSeconds":1142255,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"49142deefcd1dd5f","spanId":"75f49423cd40df70","operation":"callback-pending0 (cross thread span)","startTimeMicroSeconds":1567179155781478,"durationNanoSeconds":1766619,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"75f49423cd40df70","spanId":"aa6e6a82b568c2ec","operation":"success0","startTimeMicroSeconds":1567179155783221,"durationNanoSeconds":15098236,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"580ff7b7ad4b95f3","spanId":"96d218e038c4776b","operation":"success1","startTimeMicroSeconds":1567179155783220,"durationNanoSeconds":15094089,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"49142deefcd1dd5f","spanId":"e37d20f874a49f16","operation":"callback-pending3 (cross thread span)","startTimeMicroSeconds":1567179155782126,"durationNanoSeconds":16333485,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"49142deefcd1dd5f","spanId":"c207a951e62c91b1","operation":"callback-pending2 (cross thread span)","startTimeMicroSeconds":1567179155782115,"durationNanoSeconds":16348051,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"c207a951e62c91b1","spanId":"8bd9343a83ffa4db","operation":"success2","startTimeMicroSeconds":1567179155798443,"durationNanoSeconds":10821050,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"e37d20f874a49f16","spanId":"1db2a1fa32756d00","operation":"success3","startTimeMicroSeconds":1567179155798443,"durationNanoSeconds":10810099,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"49142deefcd1dd5f","spanId":"7e642a86c252122c","operation":"callback-pending4 (cross thread span)","startTimeMicroSeconds":1567179155782135,"durationNanoSeconds":27231966,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"49142deefcd1dd5f","spanId":"88ad8db756022b94","operation":"callback-pending5 (cross thread span)","startTimeMicroSeconds":1567179155782144,"durationNanoSeconds":27223573,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"88ad8db756022b94","spanId":"b0692a6c826fad87","operation":"success5","startTimeMicroSeconds":1567179155809360,"durationNanoSeconds":10700416,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"7e642a86c252122c","spanId":"dedf8317a9d4b288","operation":"success4","startTimeMicroSeconds":1567179155809359,"durationNanoSeconds":10762276,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"49142deefcd1dd5f","spanId":"096a8df56cb77aec","operation":"callback-pending6 (cross thread span)","startTimeMicroSeconds":1567179155782153,"durationNanoSeconds":38024975,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"49142deefcd1dd5f","spanId":"d4915e5cf7429d77","operation":"callback-pending7 (cross thread span)","startTimeMicroSeconds":1567179155782161,"durationNanoSeconds":38044235,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"096a8df56cb77aec","spanId":"b344655f74628b52","operation":"success6","startTimeMicroSeconds":1567179155820167,"durationNanoSeconds":12588624,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"d4915e5cf7429d77","spanId":"62d50ba730b7f4b2","operation":"success7","startTimeMicroSeconds":1567179155820198,"durationNanoSeconds":12570825,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"49142deefcd1dd5f","spanId":"05ad89a8326f09de","operation":"callback-pending9 (cross thread span)","startTimeMicroSeconds":1567179155782177,"durationNanoSeconds":50681074,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"49142deefcd1dd5f","spanId":"e3cea1940a9ecdd7","operation":"callback-pending8 (cross thread span)","startTimeMicroSeconds":1567179155782169,"durationNanoSeconds":50696635,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"05ad89a8326f09de","spanId":"174ed71cbb826de7","operation":"success9","startTimeMicroSeconds":1567179155832848,"durationNanoSeconds":12614440,"metadata":{}} +{"traceId":"a47a27ec8ab072c1","parentSpanId":"e3cea1940a9ecdd7","spanId":"5290244fbbc54ccc","operation":"success8","startTimeMicroSeconds":1567179155832858,"durationNanoSeconds":12607842,"metadata":{}} diff --git a/tracing-demos/src/test/resources/tracing/TracingDemos/backoffs_on_a_scheduled_executor.log b/tracing-demos/src/test/resources/tracing/TracingDemos/backoffs_on_a_scheduled_executor.log index e4d23d3f0..b9830dbbe 100644 --- a/tracing-demos/src/test/resources/tracing/TracingDemos/backoffs_on_a_scheduled_executor.log +++ b/tracing-demos/src/test/resources/tracing/TracingDemos/backoffs_on_a_scheduled_executor.log @@ -1,9 +1,4 @@ -{"traceId":"0875499283a0b645","parentSpanId":"f57bff76dda9bccd","spanId":"1f9685688afb892b","operation":"first attempt","startTimeMicroSeconds":1567081023561883,"durationNanoSeconds":107114618,"metadata":{}} -{"traceId":"0875499283a0b645","parentSpanId":"f57bff76dda9bccd","spanId":"d28d4828a150e70b","operation":"first tidying","startTimeMicroSeconds":1567081023676041,"durationNanoSeconds":200386672,"metadata":{}} -{"traceId":"0875499283a0b645","parentSpanId":"8fddcb256eeeb15a","spanId":"f57bff76dda9bccd","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567081023561824,"durationNanoSeconds":314967929,"metadata":{}} -{"traceId":"0875499283a0b645","parentSpanId":"df0540811612a1b2","spanId":"4ad94d822f100358","operation":"second attempt","startTimeMicroSeconds":1567081023777701,"durationNanoSeconds":100733508,"metadata":{}} -{"traceId":"0875499283a0b645","parentSpanId":"f65d492c10c83ecd","spanId":"2bbf7eb3b51093e2","operation":"final attempt","startTimeMicroSeconds":1567081023983056,"durationNanoSeconds":100766995,"metadata":{}} -{"traceId":"0875499283a0b645","parentSpanId":"df0540811612a1b2","spanId":"beadbcad1c24eebe","operation":"second tidying","startTimeMicroSeconds":1567081023879549,"durationNanoSeconds":204268808,"metadata":{}} -{"traceId":"0875499283a0b645","parentSpanId":"f57bff76dda9bccd","spanId":"df0540811612a1b2","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567081023777644,"durationNanoSeconds":306243186,"metadata":{}} -{"traceId":"0875499283a0b645","parentSpanId":"df0540811612a1b2","spanId":"f65d492c10c83ecd","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567081023983012,"durationNanoSeconds":100901662,"metadata":{}} -{"traceId":"0875499283a0b645","parentSpanId":null,"spanId":"8fddcb256eeeb15a","operation":"some-request","startTimeMicroSeconds":1567081023513315,"durationNanoSeconds":635798768,"metadata":{}} +{"traceId":"a9b1288b1a50a32f","parentSpanId":null,"spanId":"aea1bfae41893b23","operation":"first network call (pretending this fails)","startTimeMicroSeconds":1567179155258813,"durationNanoSeconds":103760661,"metadata":{}} +{"traceId":"b8e058ed67897372","parentSpanId":"50fe3e94c84af5ee","spanId":"e3cd9eda596108d2","operation":"backoff","startTimeMicroSeconds":1567179155362656,"durationNanoSeconds":24989226,"metadata":{}} +{"traceId":"b8e058ed67897372","parentSpanId":null,"spanId":"50fe3e94c84af5ee","operation":"overall request","startTimeMicroSeconds":1567179155255200,"durationNanoSeconds":236451599,"metadata":{}} +{"traceId":"b8e058ed67897372","parentSpanId":"e3cd9eda596108d2","spanId":"4f7b471a24b311cb","operation":"secondAttempt","startTimeMicroSeconds":1567179155387639,"durationNanoSeconds":104106473,"metadata":{}} diff --git a/tracing-demos/src/test/resources/tracing/TracingDemos/handles_async_spans.log b/tracing-demos/src/test/resources/tracing/TracingDemos/handles_async_spans.log index d973d9a0a..560af32cf 100644 --- a/tracing-demos/src/test/resources/tracing/TracingDemos/handles_async_spans.log +++ b/tracing-demos/src/test/resources/tracing/TracingDemos/handles_async_spans.log @@ -1,33 +1,40 @@ -{"traceId":"6df3ba56f991bd3c","parentSpanId":null,"spanId":"1e408d974e9a34e1","operation":"root","startTimeMicroSeconds":1567083998623608,"durationNanoSeconds":7281920,"metadata":{}} -{"traceId":"e83bc82b26726b87","parentSpanId":"b3794ecadedaf8fe","spanId":"7251b66c6e772329","operation":"sleep 100","startTimeMicroSeconds":1567083998626931,"durationNanoSeconds":100483960,"metadata":{}} -{"traceId":"a3decc2e97b3e403","parentSpanId":"b5ef64121d5f4bc7","spanId":"712cee1c0af620aa","operation":"sleep 100","startTimeMicroSeconds":1567083998626934,"durationNanoSeconds":100481955,"metadata":{}} -{"traceId":"e83bc82b26726b87","parentSpanId":"7d233f880db57a8c","spanId":"b97182bcdcf41b76","operation":"sleep 90","startTimeMicroSeconds":1567083998727620,"durationNanoSeconds":91496591,"metadata":{}} -{"traceId":"e83bc82b26726b87","parentSpanId":"b3794ecadedaf8fe","spanId":"7d233f880db57a8c","operation":"nested","startTimeMicroSeconds":1567083998727604,"durationNanoSeconds":91543922,"metadata":{}} -{"traceId":"a3decc2e97b3e403","parentSpanId":"cb641e2f9c610f10","spanId":"07d16fdd11cb1810","operation":"sleep 90","startTimeMicroSeconds":1567083998727629,"durationNanoSeconds":91758772,"metadata":{}} -{"traceId":"a3decc2e97b3e403","parentSpanId":"b5ef64121d5f4bc7","spanId":"cb641e2f9c610f10","operation":"nested","startTimeMicroSeconds":1567083998727616,"durationNanoSeconds":91793342,"metadata":{}} -{"traceId":"e83bc82b26726b87","parentSpanId":"b3794ecadedaf8fe","spanId":"72c00d665bf201ed","operation":"sleep 10","startTimeMicroSeconds":1567083998819176,"durationNanoSeconds":10291356,"metadata":{}} -{"traceId":"e83bc82b26726b87","parentSpanId":"f1387dc28ad337e5","spanId":"b3794ecadedaf8fe","operation":"first","startTimeMicroSeconds":1567083998626893,"durationNanoSeconds":202610302,"metadata":{}} -{"traceId":"a3decc2e97b3e403","parentSpanId":"b5ef64121d5f4bc7","spanId":"97b23e77a2df4262","operation":"sleep 10","startTimeMicroSeconds":1567083998819430,"durationNanoSeconds":10274735,"metadata":{}} -{"traceId":"a3decc2e97b3e403","parentSpanId":"c7791b4bedc339b2","spanId":"b5ef64121d5f4bc7","operation":"first","startTimeMicroSeconds":1567083998626894,"durationNanoSeconds":202834336,"metadata":{}} -{"traceId":"e83bc82b26726b87","parentSpanId":"b29d8d2f3dea9a66","spanId":"fc6f175a63f6fe49","operation":"sleep 100","startTimeMicroSeconds":1567083998829549,"durationNanoSeconds":101378312,"metadata":{}} -{"traceId":"a3decc2e97b3e403","parentSpanId":"1f119ea8e7d2517d","spanId":"d5c7b4e7231fabf8","operation":"sleep 100","startTimeMicroSeconds":1567083998829760,"durationNanoSeconds":101167544,"metadata":{}} -{"traceId":"e83bc82b26726b87","parentSpanId":"f1387dc28ad337e5","spanId":"b29d8d2f3dea9a66","operation":"second","startTimeMicroSeconds":1567083998829535,"durationNanoSeconds":101426029,"metadata":{}} -{"traceId":"a3decc2e97b3e403","parentSpanId":"c7791b4bedc339b2","spanId":"1f119ea8e7d2517d","operation":"second","startTimeMicroSeconds":1567083998829749,"durationNanoSeconds":101219782,"metadata":{}} -{"traceId":"e83bc82b26726b87","parentSpanId":null,"spanId":"f1387dc28ad337e5","operation":"root","startTimeMicroSeconds":1567083998626854,"durationNanoSeconds":304129572,"metadata":{}} -{"traceId":"a3decc2e97b3e403","parentSpanId":null,"spanId":"c7791b4bedc339b2","operation":"root","startTimeMicroSeconds":1567083998626878,"durationNanoSeconds":304113205,"metadata":{}} -{"traceId":"f3edabdc88434047","parentSpanId":"c7b11ea631102d7b","spanId":"128b4b2d4fdcb252","operation":"sleep 100","startTimeMicroSeconds":1567083998931344,"durationNanoSeconds":100466350,"metadata":{}} -{"traceId":"e0f23219a5aebc3a","parentSpanId":"1e358e05a94c5e17","spanId":"6440903138d7766f","operation":"sleep 100","startTimeMicroSeconds":1567083998931329,"durationNanoSeconds":104203779,"metadata":{}} -{"traceId":"f3edabdc88434047","parentSpanId":"bf4f2eb14d227e40","spanId":"efe0c95fbd6a46a5","operation":"sleep 90","startTimeMicroSeconds":1567083999031881,"durationNanoSeconds":93729812,"metadata":{}} -{"traceId":"f3edabdc88434047","parentSpanId":"c7b11ea631102d7b","spanId":"bf4f2eb14d227e40","operation":"nested","startTimeMicroSeconds":1567083999031865,"durationNanoSeconds":93776917,"metadata":{}} -{"traceId":"e0f23219a5aebc3a","parentSpanId":"073a80628f6c626f","spanId":"32c68d1223730037","operation":"sleep 90","startTimeMicroSeconds":1567083999035621,"durationNanoSeconds":90057860,"metadata":{}} -{"traceId":"e0f23219a5aebc3a","parentSpanId":"1e358e05a94c5e17","spanId":"073a80628f6c626f","operation":"nested","startTimeMicroSeconds":1567083999035603,"durationNanoSeconds":90091144,"metadata":{}} -{"traceId":"e0f23219a5aebc3a","parentSpanId":"1e358e05a94c5e17","spanId":"978e268ef2f2d4d6","operation":"sleep 10","startTimeMicroSeconds":1567083999125715,"durationNanoSeconds":10141892,"metadata":{}} -{"traceId":"e0f23219a5aebc3a","parentSpanId":"92d2cdaee0dd3b67","spanId":"1e358e05a94c5e17","operation":"first","startTimeMicroSeconds":1567083998931321,"durationNanoSeconds":204570793,"metadata":{}} -{"traceId":"f3edabdc88434047","parentSpanId":"c7b11ea631102d7b","spanId":"cc10d810db370d79","operation":"sleep 10","startTimeMicroSeconds":1567083999125671,"durationNanoSeconds":10265755,"metadata":{}} -{"traceId":"f3edabdc88434047","parentSpanId":"f98189a81ba9d8e3","spanId":"c7b11ea631102d7b","operation":"first","startTimeMicroSeconds":1567083998931333,"durationNanoSeconds":204617676,"metadata":{}} -{"traceId":"e0f23219a5aebc3a","parentSpanId":"fd3c9072acb752cf","spanId":"280d073e9e2f261b","operation":"sleep 100","startTimeMicroSeconds":1567083999135948,"durationNanoSeconds":102803249,"metadata":{}} -{"traceId":"e0f23219a5aebc3a","parentSpanId":"92d2cdaee0dd3b67","spanId":"fd3c9072acb752cf","operation":"second","startTimeMicroSeconds":1567083999135938,"durationNanoSeconds":102848516,"metadata":{}} -{"traceId":"e0f23219a5aebc3a","parentSpanId":null,"spanId":"92d2cdaee0dd3b67","operation":"root","startTimeMicroSeconds":1567083998931310,"durationNanoSeconds":307500144,"metadata":{}} -{"traceId":"f3edabdc88434047","parentSpanId":"c3b6498254604d82","spanId":"5ae9e0a0197f0bb3","operation":"sleep 100","startTimeMicroSeconds":1567083999135994,"durationNanoSeconds":105051937,"metadata":{}} -{"traceId":"f3edabdc88434047","parentSpanId":"f98189a81ba9d8e3","spanId":"c3b6498254604d82","operation":"second","startTimeMicroSeconds":1567083999135970,"durationNanoSeconds":105089543,"metadata":{}} -{"traceId":"f3edabdc88434047","parentSpanId":null,"spanId":"f98189a81ba9d8e3","operation":"root","startTimeMicroSeconds":1567083998931324,"durationNanoSeconds":309749767,"metadata":{}} +{"traceId":"176030035d9125ce","parentSpanId":null,"spanId":"41ebac16dba1fa86","operation":"task-queue-time0","startTimeMicroSeconds":1567179154587500,"durationNanoSeconds":2312836,"metadata":{}} +{"traceId":"f78c2c0415568424","parentSpanId":null,"spanId":"8b1d5782614f41c0","operation":"task-queue-time1","startTimeMicroSeconds":1567179154589588,"durationNanoSeconds":287243,"metadata":{}} +{"traceId":"f78c2c0415568424","parentSpanId":"8dfb2c5359d68ed4","spanId":"19dd47a899b399c2","operation":"sleep 100","startTimeMicroSeconds":1567179154590621,"durationNanoSeconds":102299404,"metadata":{}} +{"traceId":"176030035d9125ce","parentSpanId":"049a0278ed5bbc15","spanId":"76eaa90711d92fb6","operation":"sleep 100","startTimeMicroSeconds":1567179154590617,"durationNanoSeconds":102303728,"metadata":{}} +{"traceId":"f78c2c0415568424","parentSpanId":"36a0f2020d66434f","spanId":"f512500b5cc52df3","operation":"sleep 90","startTimeMicroSeconds":1567179154692995,"durationNanoSeconds":94457914,"metadata":{}} +{"traceId":"176030035d9125ce","parentSpanId":"00c89687a14e9b29","spanId":"a21f119c1865de62","operation":"sleep 90","startTimeMicroSeconds":1567179154693000,"durationNanoSeconds":94464780,"metadata":{}} +{"traceId":"f78c2c0415568424","parentSpanId":"8dfb2c5359d68ed4","spanId":"36a0f2020d66434f","operation":"nested","startTimeMicroSeconds":1567179154692977,"durationNanoSeconds":94546714,"metadata":{}} +{"traceId":"176030035d9125ce","parentSpanId":"049a0278ed5bbc15","spanId":"00c89687a14e9b29","operation":"nested","startTimeMicroSeconds":1567179154692977,"durationNanoSeconds":94564079,"metadata":{}} +{"traceId":"176030035d9125ce","parentSpanId":"049a0278ed5bbc15","spanId":"6667b61eebf86d54","operation":"sleep 10","startTimeMicroSeconds":1567179154787599,"durationNanoSeconds":12638021,"metadata":{}} +{"traceId":"f78c2c0415568424","parentSpanId":"8dfb2c5359d68ed4","spanId":"39f2ae0560032729","operation":"sleep 10","startTimeMicroSeconds":1567179154787583,"durationNanoSeconds":12653683,"metadata":{}} +{"traceId":"176030035d9125ce","parentSpanId":"7f6aa5a29b47155f","spanId":"049a0278ed5bbc15","operation":"first","startTimeMicroSeconds":1567179154590602,"durationNanoSeconds":209723627,"metadata":{}} +{"traceId":"f78c2c0415568424","parentSpanId":"4bb0eb9e70f14bd0","spanId":"8dfb2c5359d68ed4","operation":"first","startTimeMicroSeconds":1567179154590602,"durationNanoSeconds":209773659,"metadata":{}} +{"traceId":"f78c2c0415568424","parentSpanId":"6a2e7db1304ef445","spanId":"8a1c0752a71556ae","operation":"sleep 100","startTimeMicroSeconds":1567179154800466,"durationNanoSeconds":103032440,"metadata":{}} +{"traceId":"176030035d9125ce","parentSpanId":"806df1b790ea64c2","spanId":"e72f0ab2bdf2b8d6","operation":"sleep 100","startTimeMicroSeconds":1567179154800427,"durationNanoSeconds":103071337,"metadata":{}} +{"traceId":"f78c2c0415568424","parentSpanId":"4bb0eb9e70f14bd0","spanId":"6a2e7db1304ef445","operation":"second","startTimeMicroSeconds":1567179154800435,"durationNanoSeconds":103110887,"metadata":{}} +{"traceId":"176030035d9125ce","parentSpanId":"7f6aa5a29b47155f","spanId":"806df1b790ea64c2","operation":"second","startTimeMicroSeconds":1567179154800393,"durationNanoSeconds":103156990,"metadata":{}} +{"traceId":"f78c2c0415568424","parentSpanId":"9781efb108a88535","spanId":"4bb0eb9e70f14bd0","operation":"emit_nested_spans","startTimeMicroSeconds":1567179154590584,"durationNanoSeconds":312982552,"metadata":{}} +{"traceId":"176030035d9125ce","parentSpanId":"5231bf63c65db5cb","spanId":"7f6aa5a29b47155f","operation":"emit_nested_spans","startTimeMicroSeconds":1567179154590583,"durationNanoSeconds":312989050,"metadata":{}} +{"traceId":"f78c2c0415568424","parentSpanId":"8b1d5782614f41c0","spanId":"9781efb108a88535","operation":"task1","startTimeMicroSeconds":1567179154589872,"durationNanoSeconds":313739795,"metadata":{}} +{"traceId":"176030035d9125ce","parentSpanId":"41ebac16dba1fa86","spanId":"5231bf63c65db5cb","operation":"task0","startTimeMicroSeconds":1567179154589789,"durationNanoSeconds":313824675,"metadata":{}} +{"traceId":"8f59c9ec0be8fef0","parentSpanId":null,"spanId":"c5133147cf49ce62","operation":"task-queue-time2","startTimeMicroSeconds":1567179154589755,"durationNanoSeconds":313989392,"metadata":{}} +{"traceId":"a3f5b5118b3e3ee0","parentSpanId":null,"spanId":"ba58e523b62bcc55","operation":"task-queue-time3","startTimeMicroSeconds":1567179154589813,"durationNanoSeconds":313933381,"metadata":{}} +{"traceId":"a3f5b5118b3e3ee0","parentSpanId":"ee8998b5579dbc59","spanId":"5f9f0f452adca3c4","operation":"sleep 100","startTimeMicroSeconds":1567179154903810,"durationNanoSeconds":103206613,"metadata":{}} +{"traceId":"8f59c9ec0be8fef0","parentSpanId":"f4b2899650b13e71","spanId":"bb9991793958d418","operation":"sleep 100","startTimeMicroSeconds":1567179154903805,"durationNanoSeconds":103211893,"metadata":{}} +{"traceId":"8f59c9ec0be8fef0","parentSpanId":"998a9d77eaa8208a","spanId":"5690683d4461411c","operation":"sleep 90","startTimeMicroSeconds":1567179155009144,"durationNanoSeconds":90753895,"metadata":{}} +{"traceId":"a3f5b5118b3e3ee0","parentSpanId":"7bcd1c51438f447d","spanId":"e3af6d103204b6c0","operation":"sleep 90","startTimeMicroSeconds":1567179155007145,"durationNanoSeconds":92753245,"metadata":{}} +{"traceId":"8f59c9ec0be8fef0","parentSpanId":"f4b2899650b13e71","spanId":"998a9d77eaa8208a","operation":"nested","startTimeMicroSeconds":1567179155007111,"durationNanoSeconds":90818457,"metadata":{}} +{"traceId":"a3f5b5118b3e3ee0","parentSpanId":"ee8998b5579dbc59","spanId":"7bcd1c51438f447d","operation":"nested","startTimeMicroSeconds":1567179155007111,"durationNanoSeconds":92821594,"metadata":{}} +{"traceId":"8f59c9ec0be8fef0","parentSpanId":"f4b2899650b13e71","spanId":"a99c1919509f381b","operation":"sleep 10","startTimeMicroSeconds":1567179155099964,"durationNanoSeconds":11009238,"metadata":{}} +{"traceId":"a3f5b5118b3e3ee0","parentSpanId":"ee8998b5579dbc59","spanId":"c098a177ffb82085","operation":"sleep 10","startTimeMicroSeconds":1567179155099968,"durationNanoSeconds":11006031,"metadata":{}} +{"traceId":"8f59c9ec0be8fef0","parentSpanId":"dff26b76fdda9416","spanId":"f4b2899650b13e71","operation":"first","startTimeMicroSeconds":1567179154903790,"durationNanoSeconds":207233157,"metadata":{}} +{"traceId":"a3f5b5118b3e3ee0","parentSpanId":"295f4b54d1aa84fb","spanId":"ee8998b5579dbc59","operation":"first","startTimeMicroSeconds":1567179154903795,"durationNanoSeconds":207246002,"metadata":{}} +{"traceId":"8f59c9ec0be8fef0","parentSpanId":"3a509ff9654b200a","spanId":"dac364da48fe221f","operation":"sleep 100","startTimeMicroSeconds":1567179155111101,"durationNanoSeconds":100088506,"metadata":{}} +{"traceId":"a3f5b5118b3e3ee0","parentSpanId":"d844f831e0b95f24","spanId":"80ab631ac14c51c9","operation":"sleep 100","startTimeMicroSeconds":1567179155111102,"durationNanoSeconds":100087687,"metadata":{}} +{"traceId":"8f59c9ec0be8fef0","parentSpanId":"dff26b76fdda9416","spanId":"3a509ff9654b200a","operation":"second","startTimeMicroSeconds":1567179155111067,"durationNanoSeconds":100154897,"metadata":{}} +{"traceId":"a3f5b5118b3e3ee0","parentSpanId":"295f4b54d1aa84fb","spanId":"d844f831e0b95f24","operation":"second","startTimeMicroSeconds":1567179155111080,"durationNanoSeconds":100152595,"metadata":{}} +{"traceId":"8f59c9ec0be8fef0","parentSpanId":"ffe3f2c4f1eb6865","spanId":"dff26b76fdda9416","operation":"emit_nested_spans","startTimeMicroSeconds":1567179154903775,"durationNanoSeconds":307461835,"metadata":{}} +{"traceId":"a3f5b5118b3e3ee0","parentSpanId":"b14b1ed055d7d0d7","spanId":"295f4b54d1aa84fb","operation":"emit_nested_spans","startTimeMicroSeconds":1567179154903780,"durationNanoSeconds":307466424,"metadata":{}} +{"traceId":"8f59c9ec0be8fef0","parentSpanId":"c5133147cf49ce62","spanId":"ffe3f2c4f1eb6865","operation":"task2","startTimeMicroSeconds":1567179154903733,"durationNanoSeconds":307533908,"metadata":{}} +{"traceId":"a3f5b5118b3e3ee0","parentSpanId":"ba58e523b62bcc55","spanId":"b14b1ed055d7d0d7","operation":"task3","startTimeMicroSeconds":1567179154903733,"durationNanoSeconds":307548142,"metadata":{}} diff --git a/tracing-demos/src/test/resources/tracing/TracingDemos/multi_producer_single_consumer.log b/tracing-demos/src/test/resources/tracing/TracingDemos/multi_producer_single_consumer.log index 1d11ede45..20f18c145 100644 --- a/tracing-demos/src/test/resources/tracing/TracingDemos/multi_producer_single_consumer.log +++ b/tracing-demos/src/test/resources/tracing/TracingDemos/multi_producer_single_consumer.log @@ -1,62 +1,40 @@ -{"traceId":"7fc65698fb689a79","parentSpanId":"210c1c7db8875417","spanId":"1efd6ebadd0bd64b","operation":"submit-work0","startTimeMicroSeconds":1567085337013974,"durationNanoSeconds":39841,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"210c1c7db8875417","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337013943,"durationNanoSeconds":108897,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"a34d7d56b03cd96f","spanId":"fd9cda4a1b765ccc","operation":"submit-work1","startTimeMicroSeconds":1567085337014034,"durationNanoSeconds":24233,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"a34d7d56b03cd96f","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014019,"durationNanoSeconds":66998,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"886a1f523665c44b","spanId":"454ad9f0720d03d7","operation":"submit-work2","startTimeMicroSeconds":1567085337014138,"durationNanoSeconds":17869,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"886a1f523665c44b","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014125,"durationNanoSeconds":49184,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"61fdaaf9cd851c1c","spanId":"a20f8b6e77550e30","operation":"submit-work3","startTimeMicroSeconds":1567085337014166,"durationNanoSeconds":15948,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"61fdaaf9cd851c1c","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014154,"durationNanoSeconds":48283,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"dbe753d46ebe574c","spanId":"56d4282c4f916d97","operation":"submit-work4","startTimeMicroSeconds":1567085337014248,"durationNanoSeconds":14180,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"dbe753d46ebe574c","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014237,"durationNanoSeconds":43777,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"d57110dff3042e3a","spanId":"7ae4c867401c45a3","operation":"submit-work5","startTimeMicroSeconds":1567085337014274,"durationNanoSeconds":15565,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"d57110dff3042e3a","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014262,"durationNanoSeconds":46064,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"b25bde3e08fd4a95","spanId":"81d082ca33a0bdb2","operation":"submit-work6","startTimeMicroSeconds":1567085337014350,"durationNanoSeconds":15284,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"b25bde3e08fd4a95","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014338,"durationNanoSeconds":52926,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"3537dc0f8f9bcff7","spanId":"b6b03e342e3e00dc","operation":"submit-work7","startTimeMicroSeconds":1567085337014411,"durationNanoSeconds":15168,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"3537dc0f8f9bcff7","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014395,"durationNanoSeconds":54505,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"de0febee44ad465d","spanId":"4e1c18ba00250f34","operation":"submit-work8","startTimeMicroSeconds":1567085337014460,"durationNanoSeconds":14124,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"de0febee44ad465d","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014449,"durationNanoSeconds":44948,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"61a2a2e869daea1c","spanId":"3af1d89d88aec79d","operation":"submit-work9","startTimeMicroSeconds":1567085337014524,"durationNanoSeconds":36316,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"61a2a2e869daea1c","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014512,"durationNanoSeconds":69480,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"f86e50abc238bd55","spanId":"167055f9c7963f0d","operation":"submit-work10","startTimeMicroSeconds":1567085337014590,"durationNanoSeconds":23766,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"f86e50abc238bd55","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014578,"durationNanoSeconds":57526,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"1a6b78f7c3e18784","spanId":"d20e6599d63b406b","operation":"submit-work11","startTimeMicroSeconds":1567085337014656,"durationNanoSeconds":93000,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"0bbec5c5cfd13bf3","spanId":"6a0b7a2ebf7a0751","operation":"submit-work12","startTimeMicroSeconds":1567085337014708,"durationNanoSeconds":60551,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"1a6b78f7c3e18784","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014644,"durationNanoSeconds":125485,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"0bbec5c5cfd13bf3","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014696,"durationNanoSeconds":93112,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a1b8729f6a0996a","spanId":"53741fd9525bbd80","operation":"submit-work13","startTimeMicroSeconds":1567085337014841,"durationNanoSeconds":14399,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"6a1b8729f6a0996a","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014829,"durationNanoSeconds":44206,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"5ba3f51290af73a7","spanId":"792bb7e24a2df21c","operation":"submit-work14","startTimeMicroSeconds":1567085337014866,"durationNanoSeconds":14779,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"5ba3f51290af73a7","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014848,"durationNanoSeconds":52153,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"71b6deee963a87f5","spanId":"c52c4254ea7f3e7a","operation":"submit-work15","startTimeMicroSeconds":1567085337014942,"durationNanoSeconds":17763,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"71b6deee963a87f5","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014931,"durationNanoSeconds":49221,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"4030170f00d26fba","spanId":"6a084ae4b1b83c36","operation":"submit-work16","startTimeMicroSeconds":1567085337014969,"durationNanoSeconds":15052,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"4030170f00d26fba","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337014958,"durationNanoSeconds":43944,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"62a282a696cddfc5","spanId":"c6f1b837cd6b5fdd","operation":"submit-work17","startTimeMicroSeconds":1567085337015049,"durationNanoSeconds":16336,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"62a282a696cddfc5","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337015038,"durationNanoSeconds":45468,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"ff3733fc34b11ec5","spanId":"284574ff62d61d73","operation":"submit-work18","startTimeMicroSeconds":1567085337015072,"durationNanoSeconds":13919,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"ff3733fc34b11ec5","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337015061,"durationNanoSeconds":42458,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"4ca9f9d4b5b3e81e","spanId":"d896ee13b3fab14e","operation":"submit-work19","startTimeMicroSeconds":1567085337015154,"durationNanoSeconds":23203,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"4ca9f9d4b5b3e81e","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337015140,"durationNanoSeconds":55663,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"e1ba907d1fe2eec5","operation":"processingwork0","startTimeMicroSeconds":1567085337015824,"durationNanoSeconds":10356179,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"83997f6b6ed59275","operation":"processingwork1","startTimeMicroSeconds":1567085337026307,"durationNanoSeconds":11306856,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"cc9d9baa09c2ec84","operation":"processingwork10","startTimeMicroSeconds":1567085337037719,"durationNanoSeconds":12552373,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"022409d797133826","operation":"processingwork11","startTimeMicroSeconds":1567085337050363,"durationNanoSeconds":12496281,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"627c1d8a807b017d","operation":"processingwork12","startTimeMicroSeconds":1567085337062934,"durationNanoSeconds":11004739,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"1cc5c7a58c073a67","operation":"processingwork13","startTimeMicroSeconds":1567085337074031,"durationNanoSeconds":12593612,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"f8cf41730abfbf59","operation":"processingwork14","startTimeMicroSeconds":1567085337086771,"durationNanoSeconds":11305291,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"8880a760d2862740","operation":"processingwork15","startTimeMicroSeconds":1567085337098191,"durationNanoSeconds":11210129,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"6eedb91f5d7dc477","operation":"processingwork16","startTimeMicroSeconds":1567085337109542,"durationNanoSeconds":12596060,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"57dcc75644d32370","operation":"processingwork17","startTimeMicroSeconds":1567085337122282,"durationNanoSeconds":10576953,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"adab6f768a2dd073","operation":"processingwork18","startTimeMicroSeconds":1567085337133037,"durationNanoSeconds":12643346,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"ae1c6783f968e50b","operation":"processingwork19","startTimeMicroSeconds":1567085337145859,"durationNanoSeconds":11125043,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"31cc070a4fc2abf3","operation":"processingwork2","startTimeMicroSeconds":1567085337157131,"durationNanoSeconds":12387835,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"beb8ec56a176c8d3","operation":"processingwork3","startTimeMicroSeconds":1567085337169668,"durationNanoSeconds":10322091,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"17161680dd5e788d","operation":"processingwork4","startTimeMicroSeconds":1567085337180137,"durationNanoSeconds":11613708,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"4a15773e319efaf1","operation":"processingwork5","startTimeMicroSeconds":1567085337191860,"durationNanoSeconds":12609148,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"f63847f2296067b9","operation":"processingwork6","startTimeMicroSeconds":1567085337204625,"durationNanoSeconds":12596208,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"ae7b4b67ad58b96c","operation":"processingwork7","startTimeMicroSeconds":1567085337217371,"durationNanoSeconds":12610069,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"916d088aa2e5a9a9","operation":"processingwork8","startTimeMicroSeconds":1567085337230123,"durationNanoSeconds":12613471,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"239959a506e900e3","spanId":"314b00c6b3dfb12b","operation":"processingwork9","startTimeMicroSeconds":1567085337242867,"durationNanoSeconds":12614361,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":"6a3424d45e4ffa2b","spanId":"239959a506e900e3","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085337015777,"durationNanoSeconds":239853736,"metadata":{}} -{"traceId":"7fc65698fb689a79","parentSpanId":null,"spanId":"6a3424d45e4ffa2b","operation":"submit","startTimeMicroSeconds":1567085337011919,"durationNanoSeconds":243813430,"metadata":{}} +{"traceId":"50b900d8dbe6c9a0","parentSpanId":null,"spanId":"28a4d1d0317d1ec5","operation":"callback-pending0 (cross thread span)","startTimeMicroSeconds":1567179155501507,"durationNanoSeconds":4007792,"metadata":{}} +{"traceId":"50b900d8dbe6c9a0","parentSpanId":"28a4d1d0317d1ec5","spanId":"5e7e39cbe58ab983","operation":"consumework0","startTimeMicroSeconds":1567179155505509,"durationNanoSeconds":12579958,"metadata":{}} +{"traceId":"6bfab3252e68720c","parentSpanId":null,"spanId":"58ee422db11c0392","operation":"callback-pending1 (cross thread span)","startTimeMicroSeconds":1567179155503016,"durationNanoSeconds":15153733,"metadata":{}} +{"traceId":"6bfab3252e68720c","parentSpanId":"58ee422db11c0392","spanId":"8d1ede59e12be15a","operation":"consumework1","startTimeMicroSeconds":1567179155518167,"durationNanoSeconds":12559184,"metadata":{}} +{"traceId":"1d6d6e7ca65cf7de","parentSpanId":null,"spanId":"e8d785cf4d6ce075","operation":"callback-pending2 (cross thread span)","startTimeMicroSeconds":1567179155503168,"durationNanoSeconds":27629188,"metadata":{}} +{"traceId":"1d6d6e7ca65cf7de","parentSpanId":"e8d785cf4d6ce075","spanId":"6582b117c77e4f3d","operation":"consumework2","startTimeMicroSeconds":1567179155530792,"durationNanoSeconds":12536869,"metadata":{}} +{"traceId":"302841f6b2e46924","parentSpanId":null,"spanId":"88d316f1d122f097","operation":"callback-pending3 (cross thread span)","startTimeMicroSeconds":1567179155503226,"durationNanoSeconds":40140540,"metadata":{}} +{"traceId":"302841f6b2e46924","parentSpanId":"88d316f1d122f097","spanId":"2a1e25df6b32d90a","operation":"consumework3","startTimeMicroSeconds":1567179155543363,"durationNanoSeconds":12568984,"metadata":{}} +{"traceId":"2b1ae80539f41eae","parentSpanId":null,"spanId":"83628878fbfc122a","operation":"callback-pending4 (cross thread span)","startTimeMicroSeconds":1567179155503245,"durationNanoSeconds":52774184,"metadata":{}} +{"traceId":"2b1ae80539f41eae","parentSpanId":"83628878fbfc122a","spanId":"6c138b216ec7abb9","operation":"consumework4","startTimeMicroSeconds":1567179155556011,"durationNanoSeconds":12624928,"metadata":{}} +{"traceId":"11b7f46d12690c89","parentSpanId":null,"spanId":"64bd3d490de24aa2","operation":"callback-pending5 (cross thread span)","startTimeMicroSeconds":1567179155503563,"durationNanoSeconds":65199927,"metadata":{}} +{"traceId":"11b7f46d12690c89","parentSpanId":"64bd3d490de24aa2","spanId":"b01bbe5969b27dd7","operation":"consumework5","startTimeMicroSeconds":1567179155568740,"durationNanoSeconds":12604639,"metadata":{}} +{"traceId":"83256f209edb14eb","parentSpanId":null,"spanId":"d031e174bebbdbb4","operation":"callback-pending6 (cross thread span)","startTimeMicroSeconds":1567179155503600,"durationNanoSeconds":77887397,"metadata":{}} +{"traceId":"83256f209edb14eb","parentSpanId":"d031e174bebbdbb4","spanId":"21021526f6a3c8d1","operation":"consumework6","startTimeMicroSeconds":1567179155581477,"durationNanoSeconds":11489059,"metadata":{}} +{"traceId":"49f1b5fb982f5d09","parentSpanId":null,"spanId":"a543aaf21ddb13f9","operation":"callback-pending7 (cross thread span)","startTimeMicroSeconds":1567179155503645,"durationNanoSeconds":89420459,"metadata":{}} +{"traceId":"49f1b5fb982f5d09","parentSpanId":"a543aaf21ddb13f9","spanId":"0c1b5497daff1534","operation":"consumework7","startTimeMicroSeconds":1567179155593057,"durationNanoSeconds":12605636,"metadata":{}} +{"traceId":"db7fa8697142f7ae","parentSpanId":null,"spanId":"7685d09b092f354e","operation":"callback-pending8 (cross thread span)","startTimeMicroSeconds":1567179155503681,"durationNanoSeconds":102085071,"metadata":{}} +{"traceId":"db7fa8697142f7ae","parentSpanId":"7685d09b092f354e","spanId":"7f4e6b366f706476","operation":"consumework8","startTimeMicroSeconds":1567179155605758,"durationNanoSeconds":12317997,"metadata":{}} +{"traceId":"2f2a5dcb2caee8dd","parentSpanId":null,"spanId":"d6f522494408f854","operation":"callback-pending9 (cross thread span)","startTimeMicroSeconds":1567179155503725,"durationNanoSeconds":114431854,"metadata":{}} +{"traceId":"2f2a5dcb2caee8dd","parentSpanId":"d6f522494408f854","spanId":"cd0d3b798153b2b4","operation":"consumework9","startTimeMicroSeconds":1567179155618140,"durationNanoSeconds":12561795,"metadata":{}} +{"traceId":"a6309c1be32204dc","parentSpanId":null,"spanId":"ccf5b25861b6d08f","operation":"callback-pending10 (cross thread span)","startTimeMicroSeconds":1567179155503743,"durationNanoSeconds":127010221,"metadata":{}} +{"traceId":"a6309c1be32204dc","parentSpanId":"ccf5b25861b6d08f","spanId":"acdccb38c2edc241","operation":"consumework10","startTimeMicroSeconds":1567179155630748,"durationNanoSeconds":11866240,"metadata":{}} +{"traceId":"c35420ad51604d25","parentSpanId":null,"spanId":"e1b796a20045a5d1","operation":"callback-pending11 (cross thread span)","startTimeMicroSeconds":1567179155503850,"durationNanoSeconds":138843666,"metadata":{}} +{"traceId":"c35420ad51604d25","parentSpanId":"e1b796a20045a5d1","spanId":"3f031c1aac724c42","operation":"consumework11","startTimeMicroSeconds":1567179155642687,"durationNanoSeconds":12595121,"metadata":{}} +{"traceId":"99d332993dccfc5a","parentSpanId":null,"spanId":"522191af8221747d","operation":"callback-pending12 (cross thread span)","startTimeMicroSeconds":1567179155503885,"durationNanoSeconds":151466802,"metadata":{}} +{"traceId":"99d332993dccfc5a","parentSpanId":"522191af8221747d","spanId":"593d55f9c85ad567","operation":"consumework12","startTimeMicroSeconds":1567179155655345,"durationNanoSeconds":12562436,"metadata":{}} +{"traceId":"791f65806ad87c1c","parentSpanId":null,"spanId":"1afb4f467927972d","operation":"callback-pending13 (cross thread span)","startTimeMicroSeconds":1567179155503905,"durationNanoSeconds":164093060,"metadata":{}} +{"traceId":"791f65806ad87c1c","parentSpanId":"1afb4f467927972d","spanId":"addcf286609e7c45","operation":"consumework13","startTimeMicroSeconds":1567179155667992,"durationNanoSeconds":10527035,"metadata":{}} +{"traceId":"2375c1cdb687eedb","parentSpanId":null,"spanId":"2852cefecfb5d231","operation":"callback-pending14 (cross thread span)","startTimeMicroSeconds":1567179155503954,"durationNanoSeconds":174624506,"metadata":{}} +{"traceId":"2375c1cdb687eedb","parentSpanId":"2852cefecfb5d231","spanId":"c320fe1f20c68c0d","operation":"consumework14","startTimeMicroSeconds":1567179155678573,"durationNanoSeconds":12631227,"metadata":{}} +{"traceId":"126284dcaee0eeeb","parentSpanId":null,"spanId":"d035154cd49ae8f4","operation":"callback-pending15 (cross thread span)","startTimeMicroSeconds":1567179155503976,"durationNanoSeconds":187338227,"metadata":{}} +{"traceId":"126284dcaee0eeeb","parentSpanId":"d035154cd49ae8f4","spanId":"a6b1d607df74b2a9","operation":"consumework15","startTimeMicroSeconds":1567179155691303,"durationNanoSeconds":10076927,"metadata":{}} +{"traceId":"30230338d01054bb","parentSpanId":null,"spanId":"7964e2c1c8fc7df5","operation":"callback-pending16 (cross thread span)","startTimeMicroSeconds":1567179155503993,"durationNanoSeconds":197473467,"metadata":{}} +{"traceId":"30230338d01054bb","parentSpanId":"7964e2c1c8fc7df5","spanId":"d7e8281963b508d2","operation":"consumework16","startTimeMicroSeconds":1567179155701461,"durationNanoSeconds":10134059,"metadata":{}} +{"traceId":"aa54f0644b4228f5","parentSpanId":null,"spanId":"5dd6caf9d487151b","operation":"callback-pending17 (cross thread span)","startTimeMicroSeconds":1567179155504037,"durationNanoSeconds":207651656,"metadata":{}} +{"traceId":"aa54f0644b4228f5","parentSpanId":"5dd6caf9d487151b","spanId":"6e1aef9b3aa803c1","operation":"consumework17","startTimeMicroSeconds":1567179155711678,"durationNanoSeconds":12642382,"metadata":{}} +{"traceId":"5a492f1487ce1a0e","parentSpanId":null,"spanId":"eae8596ace5b266e","operation":"callback-pending18 (cross thread span)","startTimeMicroSeconds":1567179155504072,"durationNanoSeconds":220465071,"metadata":{}} +{"traceId":"5a492f1487ce1a0e","parentSpanId":"eae8596ace5b266e","spanId":"3ec21c0b462cc56a","operation":"consumework18","startTimeMicroSeconds":1567179155724516,"durationNanoSeconds":10779929,"metadata":{}} +{"traceId":"173c72e6e1887dc7","parentSpanId":null,"spanId":"6b72191b92ce9815","operation":"callback-pending19 (cross thread span)","startTimeMicroSeconds":1567179155504126,"durationNanoSeconds":231383222,"metadata":{}} +{"traceId":"173c72e6e1887dc7","parentSpanId":"6b72191b92ce9815","spanId":"0b7da4d94029d9f3","operation":"consumework19","startTimeMicroSeconds":1567179155735491,"durationNanoSeconds":11057095,"metadata":{}} diff --git a/tracing-demos/src/test/resources/tracing/TracingDemos/transformed_future.log b/tracing-demos/src/test/resources/tracing/TracingDemos/transformed_future.log index 0c60f1e67..9cc33130a 100644 --- a/tracing-demos/src/test/resources/tracing/TracingDemos/transformed_future.log +++ b/tracing-demos/src/test/resources/tracing/TracingDemos/transformed_future.log @@ -1,5 +1,3 @@ -{"traceId":"a6640e2cda24d499","parentSpanId":null,"spanId":"4d5de768dffc371a","operation":"root","startTimeMicroSeconds":1567085335148594,"durationNanoSeconds":7302262,"metadata":{}} -{"traceId":"a6640e2cda24d499","parentSpanId":"aa42b81f0b669f45","spanId":"584c485e1abe0e8d","operation":"first","startTimeMicroSeconds":1567085335152009,"durationNanoSeconds":100990393,"metadata":{}} -{"traceId":"a6640e2cda24d499","parentSpanId":"4d5de768dffc371a","spanId":"aa42b81f0b669f45","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085335151043,"durationNanoSeconds":102154732,"metadata":{}} -{"traceId":"a6640e2cda24d499","parentSpanId":"f1c617aeb0e16805","spanId":"5a47668355b72dd5","operation":"second","startTimeMicroSeconds":1567085335253301,"durationNanoSeconds":100526216,"metadata":{}} -{"traceId":"a6640e2cda24d499","parentSpanId":"aa42b81f0b669f45","spanId":"f1c617aeb0e16805","operation":"DeferredTracer(unnamed operation)","startTimeMicroSeconds":1567085335253276,"durationNanoSeconds":100633142,"metadata":{}} +{"traceId":"329f397ec3b7a0fe","parentSpanId":"9d83788a8b0f4ad7","spanId":"5ac0ec0a87e2435f","operation":"first transform","startTimeMicroSeconds":1567179152222200,"durationNanoSeconds":1013520284,"metadata":{}} +{"traceId":"329f397ec3b7a0fe","parentSpanId":"9d83788a8b0f4ad7","spanId":"e5e9381fe8b0fa02","operation":"second transform","startTimeMicroSeconds":1567179153239438,"durationNanoSeconds":1002827662,"metadata":{}} +{"traceId":"329f397ec3b7a0fe","parentSpanId":null,"spanId":"9d83788a8b0f4ad7","operation":"foo","startTimeMicroSeconds":1567179152163922,"durationNanoSeconds":2077780920,"metadata":{}} diff --git a/tracing-test-utils/src/main/java/com/palantir/tracing/HtmlFormatter.java b/tracing-test-utils/src/main/java/com/palantir/tracing/HtmlFormatter.java index 2f4fb55fb..bfb09baa2 100644 --- a/tracing-test-utils/src/main/java/com/palantir/tracing/HtmlFormatter.java +++ b/tracing-test-utils/src/main/java/com/palantir/tracing/HtmlFormatter.java @@ -94,7 +94,7 @@ private void renderSplitByTraceId(StringBuilder sb) { Map analyzedByTraceId = SpanAnalyzer.analyzeByTraceId(config.spans()); analyzedByTraceId.entrySet() .stream() - .sorted(Comparator.comparingLong(e1 -> e1.getValue().bounds().startMicros())) + .sorted(Comparator.comparing(e -> e.getValue().bounds())) .forEachOrdered(entry -> { SpanAnalyzer.Result analysis = entry.getValue(); renderAllSpansForOneTraceId(entry.getKey(), analysis, sb); diff --git a/tracing-test-utils/src/main/java/com/palantir/tracing/TimeBounds.java b/tracing-test-utils/src/main/java/com/palantir/tracing/TimeBounds.java index 7e9d4edae..51b9f0cbf 100644 --- a/tracing-test-utils/src/main/java/com/palantir/tracing/TimeBounds.java +++ b/tracing-test-utils/src/main/java/com/palantir/tracing/TimeBounds.java @@ -18,9 +18,15 @@ import com.palantir.tracing.api.Span; import java.util.Collection; +import java.util.Comparator; import java.util.concurrent.TimeUnit; -interface TimeBounds { +interface TimeBounds extends Comparable { + + Comparator COMPARATOR = Comparator + .comparingLong(TimeBounds::startMicros) + .thenComparing(TimeBounds::endNanos); + long startMicros(); long endNanos(); default long startNanos() { @@ -44,6 +50,11 @@ static TimeBounds fromSpans(Collection spans) { .max() .getAsLong(); return new TimeBounds() { + @Override + public int compareTo(TimeBounds other) { + return COMPARATOR.compare(this, other); + } + @Override public long startMicros() { return earliestStartMicros; diff --git a/tracing-test-utils/src/test/java/com/palantir/tracing/TestTracingExtensionDemo.java b/tracing-test-utils/src/test/java/com/palantir/tracing/TestTracingExtensionDemo.java index d16186655..3385a3bc8 100644 --- a/tracing-test-utils/src/test/java/com/palantir/tracing/TestTracingExtensionDemo.java +++ b/tracing-test-utils/src/test/java/com/palantir/tracing/TestTracingExtensionDemo.java @@ -92,8 +92,7 @@ void handles_async_spans() throws Exception { DetachedSpan detachedSpan = DetachedSpan.start("task-queue-time" + i); executorService.submit(() -> { - detachedSpan.close(); - try { + try (CloseableSpan closeableSpan = detachedSpan.completeAndStartChild("do-work-" + i)) { prod_code(); countDownLatch.countDown(); } catch (InterruptedException e) { diff --git a/tracing-test-utils/src/test/resources/tracing/TestTracingExtensionDemo/handles_async_spans.log b/tracing-test-utils/src/test/resources/tracing/TestTracingExtensionDemo/handles_async_spans.log index e87048bea..53dd699fd 100644 --- a/tracing-test-utils/src/test/resources/tracing/TestTracingExtensionDemo/handles_async_spans.log +++ b/tracing-test-utils/src/test/resources/tracing/TestTracingExtensionDemo/handles_async_spans.log @@ -1,25 +1,28 @@ -{"traceId":"fb05fd207c630bd3","parentSpanId":null,"spanId":"a3f606c72e62a710","operation":"ignored","startTimeMicroSeconds":1567076410003543,"durationNanoSeconds":12938215,"metadata":{}} -{"traceId":"73381203b2c47136","parentSpanId":null,"spanId":"3086a27c24ce815e","operation":"task-queue-time0","startTimeMicroSeconds":1567076410021179,"durationNanoSeconds":899520,"metadata":{}} -{"traceId":"b79cc4c64574aad2","parentSpanId":null,"spanId":"1e21376014cb7f61","operation":"task-queue-time1","startTimeMicroSeconds":1567076410021935,"durationNanoSeconds":193480,"metadata":{}} -{"traceId":"4ef4bff01e1b1bd9","parentSpanId":"c2d2eda8fcae8a05","spanId":"ca9788b9eea26f72","operation":"nested","startTimeMicroSeconds":1567076410126903,"durationNanoSeconds":92485899,"metadata":{}} -{"traceId":"a156e2e8780b6012","parentSpanId":"61515e65bda9e381","spanId":"dee598fcad473c48","operation":"nested","startTimeMicroSeconds":1567076410126903,"durationNanoSeconds":92471364,"metadata":{}} -{"traceId":"a156e2e8780b6012","parentSpanId":"b27a810be2a4d3e4","spanId":"61515e65bda9e381","operation":"first","startTimeMicroSeconds":1567076410022204,"durationNanoSeconds":207478610,"metadata":{}} -{"traceId":"4ef4bff01e1b1bd9","parentSpanId":"aafa74f69d59f292","spanId":"c2d2eda8fcae8a05","operation":"first","startTimeMicroSeconds":1567076410022205,"durationNanoSeconds":209009077,"metadata":{}} -{"traceId":"a156e2e8780b6012","parentSpanId":"b27a810be2a4d3e4","spanId":"f0679ccf1733c6fe","operation":"second","startTimeMicroSeconds":1567076410229819,"durationNanoSeconds":103480610,"metadata":{}} -{"traceId":"4ef4bff01e1b1bd9","parentSpanId":"aafa74f69d59f292","spanId":"31b161149a41f6fb","operation":"second","startTimeMicroSeconds":1567076410231255,"durationNanoSeconds":105083748,"metadata":{}} -{"traceId":"4ef4bff01e1b1bd9","parentSpanId":"aafa74f69d59f292","spanId":"0785b0e74e8cdbf8","operation":"third","startTimeMicroSeconds":1567076410336443,"durationNanoSeconds":100367739,"metadata":{}} -{"traceId":"a156e2e8780b6012","parentSpanId":"b27a810be2a4d3e4","spanId":"30fd313240f1a726","operation":"third","startTimeMicroSeconds":1567076410333428,"durationNanoSeconds":103376370,"metadata":{}} -{"traceId":"4ef4bff01e1b1bd9","parentSpanId":null,"spanId":"aafa74f69d59f292","operation":"root","startTimeMicroSeconds":1567076410022165,"durationNanoSeconds":414732085,"metadata":{}} -{"traceId":"a156e2e8780b6012","parentSpanId":null,"spanId":"b27a810be2a4d3e4","operation":"root","startTimeMicroSeconds":1567076410022165,"durationNanoSeconds":414732899,"metadata":{}} -{"traceId":"89d3d017d425a8b8","parentSpanId":null,"spanId":"dde59522bc8a754f","operation":"task-queue-time2","startTimeMicroSeconds":1567076410022076,"durationNanoSeconds":415233873,"metadata":{}} -{"traceId":"3c91d8db7b506203","parentSpanId":null,"spanId":"cc95737a6edc78da","operation":"task-queue-time3","startTimeMicroSeconds":1567076410022113,"durationNanoSeconds":415236592,"metadata":{}} -{"traceId":"ee346028ce297878","parentSpanId":"95f4cdd949f01ada","spanId":"7b17127136bb3acf","operation":"nested","startTimeMicroSeconds":1567076410542179,"durationNanoSeconds":94531482,"metadata":{}} -{"traceId":"b4fde51c7bc460c7","parentSpanId":"9b61e00ad0e18969","spanId":"329e74977840d096","operation":"nested","startTimeMicroSeconds":1567076410542184,"durationNanoSeconds":94547930,"metadata":{}} -{"traceId":"ee346028ce297878","parentSpanId":"145dfc9a5cd41d4d","spanId":"95f4cdd949f01ada","operation":"first","startTimeMicroSeconds":1567076410437430,"durationNanoSeconds":210367169,"metadata":{}} -{"traceId":"b4fde51c7bc460c7","parentSpanId":"03010756873e1c16","spanId":"9b61e00ad0e18969","operation":"first","startTimeMicroSeconds":1567076410437463,"durationNanoSeconds":210366339,"metadata":{}} -{"traceId":"ee346028ce297878","parentSpanId":"145dfc9a5cd41d4d","spanId":"e9c289164fbcf6d5","operation":"second","startTimeMicroSeconds":1567076410647902,"durationNanoSeconds":100436401,"metadata":{}} -{"traceId":"b4fde51c7bc460c7","parentSpanId":"03010756873e1c16","spanId":"78c75f4d3301d52f","operation":"second","startTimeMicroSeconds":1567076410647916,"durationNanoSeconds":100423700,"metadata":{}} -{"traceId":"b4fde51c7bc460c7","parentSpanId":"03010756873e1c16","spanId":"ed16a3a693d71691","operation":"third","startTimeMicroSeconds":1567076410748416,"durationNanoSeconds":105060552,"metadata":{}} -{"traceId":"ee346028ce297878","parentSpanId":"145dfc9a5cd41d4d","spanId":"c0415110599c666d","operation":"third","startTimeMicroSeconds":1567076410748416,"durationNanoSeconds":105061139,"metadata":{}} -{"traceId":"ee346028ce297878","parentSpanId":null,"spanId":"145dfc9a5cd41d4d","operation":"root","startTimeMicroSeconds":1567076410437401,"durationNanoSeconds":416156329,"metadata":{}} -{"traceId":"b4fde51c7bc460c7","parentSpanId":null,"spanId":"03010756873e1c16","operation":"root","startTimeMicroSeconds":1567076410437436,"durationNanoSeconds":416123118,"metadata":{}} +{"traceId":"6c07650507d1dc08","parentSpanId":null,"spanId":"c12ba93b80b19725","operation":"task-queue-time1","startTimeMicroSeconds":1567180389235355,"durationNanoSeconds":11956324,"metadata":{}} +{"traceId":"40ea321658713d40","parentSpanId":null,"spanId":"345ff4aaa39923ce","operation":"task-queue-time0","startTimeMicroSeconds":1567180389233283,"durationNanoSeconds":13815322,"metadata":{}} +{"traceId":"6c07650507d1dc08","parentSpanId":"9aaaba8e95703e3b","spanId":"82d2fbbf0ffe1d8d","operation":"nested","startTimeMicroSeconds":1567180389355806,"durationNanoSeconds":92813862,"metadata":{}} +{"traceId":"40ea321658713d40","parentSpanId":"89cea9cc4fa0b10c","spanId":"bad26157fdb995c5","operation":"nested","startTimeMicroSeconds":1567180389357275,"durationNanoSeconds":92511278,"metadata":{}} +{"traceId":"6c07650507d1dc08","parentSpanId":"b195ba88d5824279","spanId":"9aaaba8e95703e3b","operation":"first","startTimeMicroSeconds":1567180389252203,"durationNanoSeconds":206768430,"metadata":{}} +{"traceId":"40ea321658713d40","parentSpanId":"33ab81c11132cc7b","spanId":"89cea9cc4fa0b10c","operation":"first","startTimeMicroSeconds":1567180389252205,"durationNanoSeconds":208875710,"metadata":{}} +{"traceId":"6c07650507d1dc08","parentSpanId":"b195ba88d5824279","spanId":"1e46d0536294cb22","operation":"second","startTimeMicroSeconds":1567180389459086,"durationNanoSeconds":102914472,"metadata":{}} +{"traceId":"40ea321658713d40","parentSpanId":"33ab81c11132cc7b","spanId":"71baa3b92a2bfbd0","operation":"second","startTimeMicroSeconds":1567180389461291,"durationNanoSeconds":103817429,"metadata":{}} +{"traceId":"6c07650507d1dc08","parentSpanId":"b195ba88d5824279","spanId":"d2a62d17e0ee6b9d","operation":"third","startTimeMicroSeconds":1567180389562054,"durationNanoSeconds":100297042,"metadata":{}} +{"traceId":"6c07650507d1dc08","parentSpanId":"1548c30c6729037d","spanId":"b195ba88d5824279","operation":"root","startTimeMicroSeconds":1567180389252176,"durationNanoSeconds":410200444,"metadata":{}} +{"traceId":"6c07650507d1dc08","parentSpanId":"c12ba93b80b19725","spanId":"1548c30c6729037d","operation":"do-work-1","startTimeMicroSeconds":1567180389235844,"durationNanoSeconds":426606576,"metadata":{}} +{"traceId":"728f25e13273afbc","parentSpanId":null,"spanId":"496b37af19273ce8","operation":"task-queue-time2","startTimeMicroSeconds":1567180389235585,"durationNanoSeconds":427118831,"metadata":{}} +{"traceId":"40ea321658713d40","parentSpanId":"33ab81c11132cc7b","spanId":"f4d2eb496e161036","operation":"third","startTimeMicroSeconds":1567180389565173,"durationNanoSeconds":102737254,"metadata":{}} +{"traceId":"40ea321658713d40","parentSpanId":"0a79a630253e60e8","spanId":"33ab81c11132cc7b","operation":"root","startTimeMicroSeconds":1567180389252175,"durationNanoSeconds":415874032,"metadata":{}} +{"traceId":"40ea321658713d40","parentSpanId":"345ff4aaa39923ce","spanId":"0a79a630253e60e8","operation":"do-work-0","startTimeMicroSeconds":1567180389235842,"durationNanoSeconds":432310999,"metadata":{}} +{"traceId":"763ac38b7084b7a2","parentSpanId":null,"spanId":"b731b1e07a753687","operation":"task-queue-time3","startTimeMicroSeconds":1567180389235726,"durationNanoSeconds":432683852,"metadata":{}} +{"traceId":"728f25e13273afbc","parentSpanId":"dddb06e55afd267d","spanId":"8a3781b86bca101e","operation":"nested","startTimeMicroSeconds":1567180389762814,"durationNanoSeconds":91707310,"metadata":{}} +{"traceId":"728f25e13273afbc","parentSpanId":"2425a8e153aba4a5","spanId":"dddb06e55afd267d","operation":"first","startTimeMicroSeconds":1567180389662740,"durationNanoSeconds":202367506,"metadata":{}} +{"traceId":"763ac38b7084b7a2","parentSpanId":"a9cf29d7b3a897d4","spanId":"47d6e78e62c3c6ae","operation":"nested","startTimeMicroSeconds":1567180389770660,"durationNanoSeconds":94458397,"metadata":{}} +{"traceId":"763ac38b7084b7a2","parentSpanId":"d5f32648b32b1fda","spanId":"a9cf29d7b3a897d4","operation":"first","startTimeMicroSeconds":1567180389668476,"durationNanoSeconds":209189854,"metadata":{}} +{"traceId":"728f25e13273afbc","parentSpanId":"2425a8e153aba4a5","spanId":"0621793b86c4414c","operation":"second","startTimeMicroSeconds":1567180389865158,"durationNanoSeconds":102206544,"metadata":{}} +{"traceId":"763ac38b7084b7a2","parentSpanId":"d5f32648b32b1fda","spanId":"ac12732df8cc23a1","operation":"second","startTimeMicroSeconds":1567180389877692,"durationNanoSeconds":100850765,"metadata":{}} +{"traceId":"728f25e13273afbc","parentSpanId":"2425a8e153aba4a5","spanId":"6d9e9f03633a839b","operation":"third","startTimeMicroSeconds":1567180389967424,"durationNanoSeconds":101759781,"metadata":{}} +{"traceId":"728f25e13273afbc","parentSpanId":"6e7fb2e7fac2e8b5","spanId":"2425a8e153aba4a5","operation":"root","startTimeMicroSeconds":1567180389662731,"durationNanoSeconds":406481416,"metadata":{}} +{"traceId":"728f25e13273afbc","parentSpanId":"496b37af19273ce8","spanId":"6e7fb2e7fac2e8b5","operation":"do-work-2","startTimeMicroSeconds":1567180389662701,"durationNanoSeconds":406537305,"metadata":{}} +{"traceId":"763ac38b7084b7a2","parentSpanId":"d5f32648b32b1fda","spanId":"9b32b58ae93d75f0","operation":"third","startTimeMicroSeconds":1567180389978590,"durationNanoSeconds":105021266,"metadata":{}} +{"traceId":"763ac38b7084b7a2","parentSpanId":"022b58a6a4193c5c","spanId":"d5f32648b32b1fda","operation":"root","startTimeMicroSeconds":1567180389668464,"durationNanoSeconds":415157110,"metadata":{}} +{"traceId":"763ac38b7084b7a2","parentSpanId":"b731b1e07a753687","spanId":"022b58a6a4193c5c","operation":"do-work-3","startTimeMicroSeconds":1567180389668381,"durationNanoSeconds":415259337,"metadata":{}} diff --git a/tracing/src/main/java/com/palantir/tracing/SpanToken.java b/tracing/src/main/java/com/palantir/tracing/CloseableSpan.java similarity index 89% rename from tracing/src/main/java/com/palantir/tracing/SpanToken.java rename to tracing/src/main/java/com/palantir/tracing/CloseableSpan.java index 484919df0..85f89757e 100644 --- a/tracing/src/main/java/com/palantir/tracing/SpanToken.java +++ b/tracing/src/main/java/com/palantir/tracing/CloseableSpan.java @@ -21,10 +21,10 @@ /** * Closeable marker around a tracing span operation. This object should be used in a try/with block. */ -public interface SpanToken extends Closeable { +public interface CloseableSpan extends Closeable { /** - * Completes the Span marked by this {@link SpanToken}. + * Completes the Span marked by this {@link CloseableSpan}. *

* {@link #close} must be invoked on the same thread which started this span. */ diff --git a/tracing/src/main/java/com/palantir/tracing/CloseableTracer.java b/tracing/src/main/java/com/palantir/tracing/CloseableTracer.java index c32cd3710..a81174466 100644 --- a/tracing/src/main/java/com/palantir/tracing/CloseableTracer.java +++ b/tracing/src/main/java/com/palantir/tracing/CloseableTracer.java @@ -42,6 +42,8 @@ public static CloseableTracer startSpan(String operation) { /** * Opens a new span for this thread's call trace with the provided {@link SpanType}, * labeled with the provided operation. + * + * If you need to a span that may complete on another thread, use {@link DetachedSpan#start} instead. */ public static CloseableTracer startSpan(String operation, SpanType spanType) { Tracer.fastStartSpan(operation, spanType); diff --git a/tracing/src/main/java/com/palantir/tracing/DetachedSpan.java b/tracing/src/main/java/com/palantir/tracing/DetachedSpan.java index 8bad10539..db41882cf 100644 --- a/tracing/src/main/java/com/palantir/tracing/DetachedSpan.java +++ b/tracing/src/main/java/com/palantir/tracing/DetachedSpan.java @@ -18,19 +18,20 @@ import com.google.errorprone.annotations.MustBeClosed; import com.palantir.tracing.api.SpanType; -import java.io.Closeable; import javax.annotation.CheckReturnValue; -/** - * Span operation which is not bound to thread state, and can measure operations which - * themselves aren't bound to individual threads. - */ -public interface DetachedSpan extends Closeable { +/** Span which is not bound to thread state, and can be completed on any other thread. */ +public interface DetachedSpan { /** - * Like {@link Tracer#startSpan(String, SpanType)}, but does not set or modify tracing thread state. - * Creates a detached child span using the callers current span as a parent, if it is present, otherwise - * creates a detached root span with a new traceId. + * Marks the beginning of a span, which you can {@link #complete} on any other thread. Further work on this + * originating thread will not automatically parented to this span (because it does not modify any thread local + * tracing state). If you don't need this cross-thread functionality, use {@link CloseableTracer}. + * + * On the destination thread, you can call {@link #completeAndStartChild} to mark the end of this + * {@link DetachedSpan} and continue tracing regular thread-local work. Alternatively, if you want to keep this + * DetachedSpan open, you can instrument 'sub tasks' using {@link #childSpan} or {@link #childDetachedSpan}, + * but must remember to call {@link #complete} eventually. */ @CheckReturnValue static DetachedSpan start(String operation, SpanType type) { @@ -51,34 +52,46 @@ static DetachedSpan start(String operation) { * as the parent instead of thread state. */ @MustBeClosed - SpanToken attach(String operationName, SpanType type); + CloseableSpan childSpan(String operationName, SpanType type); /** * Equivalent to {@link Tracer#startSpan(String)}, but using this {@link DetachedSpan} as the parent instead * of thread state. */ @MustBeClosed - default SpanToken attach(String operationName) { - return attach(operationName, SpanType.LOCAL); + default CloseableSpan childSpan(String operationName) { + return childSpan(operationName, SpanType.LOCAL); + } + + @MustBeClosed + @SuppressWarnings("MustBeClosedChecker") + default CloseableSpan completeAndStartChild(String operationName, SpanType type) { + CloseableSpan child = childSpan(operationName, type); + complete(); + return child; + } + + @MustBeClosed + default CloseableSpan completeAndStartChild(String operationName) { + return completeAndStartChild(operationName, SpanType.LOCAL); } /** Starts a child {@link DetachedSpan} using this instance as the parent. */ @CheckReturnValue - DetachedSpan detach(String operation, SpanType type); + DetachedSpan childDetachedSpan(String operation, SpanType type); /** * Starts a child {@link DetachedSpan} using this instance as the parent. - * Equivalent to {@link #attach(String, SpanType)} using {@link SpanType#LOCAL}. + * Equivalent to {@link #childSpan(String, SpanType)} using {@link SpanType#LOCAL}. */ @CheckReturnValue - default DetachedSpan detach(String operation) { - return detach(operation, SpanType.LOCAL); + default DetachedSpan childDetachedSpan(String operation) { + return childDetachedSpan(operation, SpanType.LOCAL); } /** * Completes this span. After complete is invoked, other methods are not expected to produce spans, but * they must not throw either in order to avoid confusing failures. */ - @Override - void close(); + void complete(); } diff --git a/tracing/src/main/java/com/palantir/tracing/Tracer.java b/tracing/src/main/java/com/palantir/tracing/Tracer.java index d1282e530..65a9789f3 100644 --- a/tracing/src/main/java/com/palantir/tracing/Tracer.java +++ b/tracing/src/main/java/com/palantir/tracing/Tracer.java @@ -20,8 +20,10 @@ import static com.palantir.logsafe.Preconditions.checkNotNull; import static com.palantir.logsafe.Preconditions.checkState; +import com.google.common.annotations.VisibleForTesting; import com.google.common.base.Strings; import com.google.errorprone.annotations.CheckReturnValue; +import com.google.errorprone.annotations.MustBeClosed; import com.palantir.logsafe.Preconditions; import com.palantir.logsafe.SafeArg; import com.palantir.logsafe.UnsafeArg; @@ -200,22 +202,23 @@ private static final class SampledDetachedSpan implements DetachedSpan { } @Override - public SpanToken attach(String operationName, SpanType type) { + @MustBeClosed + public CloseableSpan childSpan(String operationName, SpanType type) { warnIfCompleted("startSpanOnCurrentThread"); Trace maybeCurrentTrace = currentTrace.get(); setTrace(Trace.of(true, traceId)); Tracer.fastStartSpan(operationName, openSpan.getSpanId(), type); - return TraceRestoringSpanToken.of(maybeCurrentTrace); + return TraceRestoringCloseableSpan.of(maybeCurrentTrace); } @Override - public DetachedSpan detach(String operation, SpanType type) { + public DetachedSpan childDetachedSpan(String operation, SpanType type) { warnIfCompleted("startDetachedSpan"); return new SampledDetachedSpan(operation, type, traceId, Optional.of(openSpan.getSpanId())); } @Override - public void close() { + public void complete() { if (completed.compareAndSet(false, true)) { Tracer.notifyObservers(toSpan(openSpan, Collections.emptyMap(), traceId)); } @@ -245,20 +248,20 @@ private static final class UnsampledDetachedSpan implements DetachedSpan { } @Override - public SpanToken attach(String operationName, SpanType type) { + public CloseableSpan childSpan(String operationName, SpanType type) { Trace maybeCurrentTrace = currentTrace.get(); setTrace(Trace.of(false, traceId)); Tracer.fastStartSpan(operationName, type); - return TraceRestoringSpanToken.of(maybeCurrentTrace); + return TraceRestoringCloseableSpan.of(maybeCurrentTrace); } @Override - public DetachedSpan detach(String operation, SpanType type) { + public DetachedSpan childDetachedSpan(String operation, SpanType type) { return this; } @Override - public void close() { + public void complete() { // nop } @@ -268,18 +271,18 @@ public String toString() { } } - private static final class TraceRestoringSpanToken implements SpanToken { + private static final class TraceRestoringCloseableSpan implements CloseableSpan { // Complete the current span. - private static final SpanToken DEFAULT_TOKEN = Tracer::fastCompleteSpan; + private static final CloseableSpan DEFAULT_TOKEN = Tracer::fastCompleteSpan; private final Trace original; - static SpanToken of(@Nullable Trace original) { - return original == null ? DEFAULT_TOKEN : new TraceRestoringSpanToken(original); + static CloseableSpan of(@Nullable Trace original) { + return original == null ? DEFAULT_TOKEN : new TraceRestoringCloseableSpan(original); } - TraceRestoringSpanToken(Trace original) { + TraceRestoringCloseableSpan(Trace original) { this.original = Preconditions.checkNotNull(original, "Expected an original trace instance"); } @@ -514,7 +517,8 @@ private static Trace getOrCreateCurrentTrace() { return trace; } - private static void clearCurrentTrace() { + @VisibleForTesting + static void clearCurrentTrace() { currentTrace.remove(); MDC.remove(Tracers.TRACE_ID_KEY); MDC.remove(Tracers.TRACE_SAMPLED_KEY); diff --git a/tracing/src/test/java/com/palantir/tracing/TracerTest.java b/tracing/src/test/java/com/palantir/tracing/TracerTest.java index 286c504bc..e9d63cbe1 100644 --- a/tracing/src/test/java/com/palantir/tracing/TracerTest.java +++ b/tracing/src/test/java/com/palantir/tracing/TracerTest.java @@ -366,7 +366,7 @@ public void testSimpleDetachedTrace() { .describedAs("Detached spans should not set thread state") .isFalse(); } finally { - detached.close(); + detached.complete(); } verify(observer1).consume(spanCaptor.capture()); assertThat(spanCaptor.getValue().getOperation()).isEqualTo(operation); @@ -382,14 +382,14 @@ public void testDetachedTraceAppliedToThreadState() { DetachedSpan detached = DetachedSpan.start(operation1); try { assertThat(Tracer.hasTraceId()).isFalse(); - try (SpanToken ignored = detached.attach(operation2)) { + try (CloseableSpan ignored = detached.childSpan(operation2)) { assertThat(Tracer.hasTraceId()).isTrue(); } verify(observer1).consume(spanCaptor.capture()); assertThat(spanCaptor.getValue().getOperation()).isEqualTo(operation2); assertThat(Tracer.hasTraceId()).isFalse(); } finally { - detached.close(); + detached.complete(); } assertThat(Tracer.hasTraceId()).isFalse(); Tracer.unsubscribe("1"); @@ -401,7 +401,7 @@ public void testDetachedTraceRestoresTrace() { DetachedSpan detached = DetachedSpan.start("detached"); Tracer.fastStartSpan("standard"); String standardTraceId = Tracer.getTraceId(); - try (SpanToken ignored = detached.attach("operation")) { + try (CloseableSpan ignored = detached.childSpan("operation")) { assertThat(Tracer.getTraceId()) .describedAs("The detached span should have a different trace") .isNotEqualTo(standardTraceId); @@ -410,7 +410,7 @@ public void testDetachedTraceRestoresTrace() { .describedAs("The detached span restores the original trace") .isEqualTo(standardTraceId); Tracer.fastCompleteSpan(); - detached.close(); + detached.complete(); assertThat(Tracer.hasTraceId()).isEqualTo(false); } @@ -422,7 +422,7 @@ public void testDetachedTraceRestoresOriginalTrace() { assertThat(Tracer.hasTraceId()).isEqualTo(false); try (CloseableTracer outer = CloseableTracer.startSpan("root")) { assertThat(Tracer.hasTraceId()).isEqualTo(true); - DetachedSpan.start("detached").close(); + DetachedSpan.start("detached").complete(); assertThat(Tracer.hasTraceId()).isEqualTo(true); } assertThat(Tracer.hasTraceId()).isEqualTo(false); @@ -442,13 +442,13 @@ public void testDetachedTraceBuildsUponExistingTrace() { Tracer.fastStartSpan("standard"); DetachedSpan detached = DetachedSpan.start("detached"); String standardTraceId = Tracer.getTraceId(); - try (SpanToken ignored = detached.attach("operation")) { + try (CloseableSpan ignored = detached.childSpan("operation")) { assertThat(Tracer.getTraceId()).isEqualTo(standardTraceId); } assertThat(Tracer.getTraceId()).isEqualTo(standardTraceId); Tracer.fastCompleteSpan(); assertThat(Tracer.hasTraceId()).isEqualTo(false); - detached.close(); + detached.complete(); assertThat(Tracer.hasTraceId()).isEqualTo(false); verify(sampler, times(1)).sample(); ArgumentCaptor captor = ArgumentCaptor.forClass(Span.class);