From 11e520c70d2f80f429f67b4e71b587032d0035b0 Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Fri, 29 Jul 2016 23:29:31 +0200 Subject: [PATCH] Updating the duration setting (#360) * Updating the duration setting fixes #349 --- .../springframework/cloud/sleuth/Span.java | 4 +++ .../stream/ConvertToZipkinSpanList.java | 28 +++++++++++++++++- .../stream/ConvertToZipkinSpanListTests.java | 24 +++++++++++++++ .../sleuth/zipkin/ZipkinSpanListener.java | 29 ++++++++++++++++++- .../zipkin/ZipkinSpanListenerTests.java | 23 ++++++++++++++- 5 files changed, 105 insertions(+), 3 deletions(-) diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/Span.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/Span.java index 37c41ab94..250f7a11d 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/Span.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/Span.java @@ -251,6 +251,10 @@ public class Span { * Return the total amount of time elapsed since start was called, if running, or * difference between stop and start, in microseconds. * + * Note that in case of the spans that have CS / CR events we will not + * send to Zipkin the accumulated microseconds but will calculate the + * duration basing on the timestamps of the CS / CR events. + * * @return zero if not running, or a positive number of microseconds. */ @JsonIgnore diff --git a/spring-cloud-sleuth-zipkin-stream/src/main/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanList.java b/spring-cloud-sleuth-zipkin-stream/src/main/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanList.java index b086c876f..930f5a5ef 100644 --- a/spring-cloud-sleuth-zipkin-stream/src/main/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanList.java +++ b/spring-cloud-sleuth-zipkin-stream/src/main/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanList.java @@ -91,7 +91,7 @@ final class ConvertToZipkinSpanList { } zipkinSpan.timestamp(span.getBegin() * 1000); if (!span.isRunning()) { // duration is authoritative, only write when the span stopped - zipkinSpan.duration(span.getAccumulatedMicros()); + zipkinSpan.duration(calculateDurationInMicros(span)); } zipkinSpan.traceId(span.getTraceId()); if (span.getParents().size() > 0) { @@ -146,4 +146,30 @@ final class ConvertToZipkinSpanList { return false; } + /** + * There could be instrumentation delay between span creation and the + * semantic start of the span (client send). When there's a difference, + * spans look confusing. Ex users expect duration to be client + * receive - send, but it is a little more than that. Rather than have + * to teach each user about the possibility of instrumentation overhead, + * we truncate absolute duration (span finish - create) to semantic + * duration (client receive - send) + */ + private static long calculateDurationInMicros(Span span) { + org.springframework.cloud.sleuth.Log clientSend = hasLog(Span.CLIENT_SEND, span); + org.springframework.cloud.sleuth.Log clientReceived = hasLog(Span.CLIENT_RECV, span); + if (clientSend != null && clientReceived != null) { + return (clientReceived.getTimestamp() - clientSend.getTimestamp()) * 1000; + } + return span.getAccumulatedMicros(); + } + + private static org.springframework.cloud.sleuth.Log hasLog(String logName, Span span) { + for (org.springframework.cloud.sleuth.Log log : span.logs()) { + if (logName.equals(log.getEvent())) { + return log; + } + } + return null; + } } \ No newline at end of file diff --git a/spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanListTests.java b/spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanListTests.java index ff282ff70..09635824d 100644 --- a/spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanListTests.java +++ b/spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanListTests.java @@ -128,6 +128,30 @@ public class ConvertToZipkinSpanListTests { .isLessThanOrEqualTo(System.currentTimeMillis() * 1000); } + @Test + public void setsTheDurationToTheDifferenceBetweenCRandCS() + throws InterruptedException { + Span span = span("foo"); + span.logEvent(Span.CLIENT_SEND); + Thread.sleep(10); + span.logEvent(Span.CLIENT_RECV); + Thread.sleep(20); + span.stop(); + + Spans spans = new Spans(this.host, Collections.singletonList(span)); + zipkin.Span result = ConvertToZipkinSpanList.convert(spans).get(0); + + assertThat(result.timestamp) + .isEqualTo(span.getBegin() * 1000); + long clientSendTimestamp = span.logs().stream().filter(log -> Span.CLIENT_SEND.equals(log.getEvent())) + .findFirst().get().getTimestamp(); + long clientRecvTimestamp = span.logs().stream().filter(log -> Span.CLIENT_RECV.equals(log.getEvent())) + .findFirst().get().getTimestamp(); + assertThat(result.duration) + .isNotEqualTo(span.getAccumulatedMicros()) + .isEqualTo((clientRecvTimestamp - clientSendTimestamp) * 1000); + } + /** Zipkin's duration should only be set when the span is finished. */ @Test public void doesntSetDurationWhenStillRunning() { diff --git a/spring-cloud-sleuth-zipkin/src/main/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListener.java b/spring-cloud-sleuth-zipkin/src/main/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListener.java index 36858de6a..ad63f007b 100644 --- a/spring-cloud-sleuth-zipkin/src/main/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListener.java +++ b/spring-cloud-sleuth-zipkin/src/main/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListener.java @@ -87,7 +87,7 @@ public class ZipkinSpanListener implements SpanReporter { } zipkinSpan.timestamp(span.getBegin() * 1000L); if (!span.isRunning()) { // duration is authoritative, only write when the span stopped - zipkinSpan.duration(span.getAccumulatedMicros()); + zipkinSpan.duration(calculateDurationInMicros(span)); } zipkinSpan.traceId(span.getTraceId()); if (span.getParents().size() > 0) { @@ -173,6 +173,33 @@ public class ZipkinSpanListener implements SpanReporter { } } + /** + * There could be instrumentation delay between span creation and the + * semantic start of the span (client send). When there's a difference, + * spans look confusing. Ex users expect duration to be client + * receive - send, but it is a little more than that. Rather than have + * to teach each user about the possibility of instrumentation overhead, + * we truncate absolute duration (span finish - create) to semantic + * duration (client receive - send) + */ + private long calculateDurationInMicros(Span span) { + org.springframework.cloud.sleuth.Log clientSend = hasLog(Span.CLIENT_SEND, span); + org.springframework.cloud.sleuth.Log clientReceived = hasLog(Span.CLIENT_RECV, span); + if (clientSend != null && clientReceived != null) { + return (clientReceived.getTimestamp() - clientSend.getTimestamp()) * 1000; + } + return span.getAccumulatedMicros(); + } + + private org.springframework.cloud.sleuth.Log hasLog(String logName, Span span) { + for (org.springframework.cloud.sleuth.Log log : span.logs()) { + if (logName.equals(log.getEvent())) { + return log; + } + } + return null; + } + @Override public void report(Span span) { if (span.isExportable()) { diff --git a/spring-cloud-sleuth-zipkin/src/test/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListenerTests.java b/spring-cloud-sleuth-zipkin/src/test/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListenerTests.java index 1b9a2cb4a..58f016e97 100644 --- a/spring-cloud-sleuth-zipkin/src/test/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListenerTests.java +++ b/spring-cloud-sleuth-zipkin/src/test/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListenerTests.java @@ -18,7 +18,6 @@ package org.springframework.cloud.sleuth.zipkin; import java.util.ArrayList; import java.util.List; - import javax.annotation.PostConstruct; import org.junit.Test; @@ -80,6 +79,28 @@ public class ZipkinSpanListenerTests { .isLessThanOrEqualTo(System.currentTimeMillis() * 1000); } + @Test + public void setsTheDurationToTheDifferenceBetweenCRandCS() + throws InterruptedException { + this.parent.logEvent(Span.CLIENT_SEND); + Thread.sleep(10); + this.parent.logEvent(Span.CLIENT_RECV); + Thread.sleep(20); + this.parent.stop(); + + zipkin.Span result = this.spanReporter.convert(this.parent); + + assertThat(result.timestamp) + .isEqualTo(this.parent.getBegin() * 1000); + long clientSendTimestamp = this.parent.logs().stream().filter(log -> Span.CLIENT_SEND.equals(log.getEvent())) + .findFirst().get().getTimestamp(); + long clientRecvTimestamp = this.parent.logs().stream().filter(log -> Span.CLIENT_RECV.equals(log.getEvent())) + .findFirst().get().getTimestamp(); + assertThat(result.duration) + .isNotEqualTo(this.parent.getAccumulatedMicros()) + .isEqualTo((clientRecvTimestamp - clientSendTimestamp) * 1000); + } + /** Zipkin's duration should only be set when the span is finished. */ @Test public void doesntSetDurationWhenStillRunning() {