From 6b5fa63553bd735ee9f14f51ac868440a3d9b7bf Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Wed, 29 Jun 2016 10:44:00 +0200 Subject: [PATCH] Exposes getAccumulatedMicros for more precise Span duration (#317) Formerly, `Span.getAccumulatedMillis()` worked, but could returns imprecise measurements, particularly local spans. This changes the internals of Span to keep track of a start tick. Using this, it can return a more precise `Span.getAccumulatedMicros()`. To ensure this precision isn't lost in serialization, this adds a json field `durationMicros`, which is only set when the span is stopped. This is set instead of start tick because `System.nanoTime()` is JVM specific and so cannot be used across the network. `durationMicros` uses null instead of zero comparisons because nano time can be negative. Fixes #312 Fixed integration tests to use ZipkinRule Introduce assertj assertions (#315) * Introduce assertJ assertions in some tests * Fix code formatting to be inline with Spring rules --- .../springframework/cloud/sleuth/Span.java | 69 ++++++++++++++++--- .../cloud/sleuth/trace/DefaultTracer.java | 6 +- .../cloud/sleuth/SpanTests.java | 21 ++++++ .../stream/ConvertToZipkinSpanList.java | 4 +- .../stream/ConvertToZipkinSpanListTests.java | 33 +++++++++ .../sleuth/zipkin/ZipkinSpanListener.java | 4 +- .../zipkin/ZipkinSpanListenerTests.java | 15 +++- 7 files changed, 134 insertions(+), 18 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 5034aad0f..29b8a0d59 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 @@ -145,6 +145,11 @@ public class Span { private final List logs; private final Span savedSpan; + // Null means we don't know the start tick, so fallback to time + @JsonIgnore + private final Long startNanos; + private Long durationMicros; // serialized in json so micros precision isn't lost + @SuppressWarnings("unused") private Span() { this(-1, -1, "dummy", 0, Collections.emptyList(), 0, false, false, null); @@ -167,6 +172,8 @@ public class Span { this.processId = current.getProcessId(); this.tags = current.tags; this.logs = current.logs; + this.startNanos = current.startNanos; + this.durationMicros = current.durationMicros; this.savedSpan = savedSpan; } @@ -179,8 +186,17 @@ public class Span { public Span(long begin, long end, String name, long traceId, List parents, long spanId, boolean remote, boolean exportable, String processId, Span savedSpan) { - this.begin = begin <= 0 ? System.currentTimeMillis() : begin; - this.end = end; + if (begin > 0) { // conventionally, 0 indicates unset + this.startNanos = null; // don't know the start tick + this.begin = begin; + } else { + this.startNanos = System.nanoTime(); + this.begin = System.currentTimeMillis(); + } + if (end > 0) { + this.end = end; + this.durationMicros = (end - begin) * 1000; + } this.name = name != null ? name : ""; this.traceId = traceId; this.parents = parents; @@ -201,28 +217,52 @@ public class Span { * The block has completed, stop the clock */ public synchronized void stop() { - if (this.end == 0) { + if (this.durationMicros == null) { if (this.begin == 0) { throw new IllegalStateException( "Span for " + this.name + " has not been started"); } - this.end = System.currentTimeMillis(); + if (this.end == 0) { + this.end = System.currentTimeMillis(); + } + if (this.startNanos != null) { // set a precise duration + this.durationMicros = (System.nanoTime() - this.startNanos) / 1000; + } else { + this.durationMicros = (this.end - this.begin) * 1000; + } } } /** * Return the total amount of time elapsed since start was called, if running, or * difference between stop and start + * + * @deprecated use {@link #getAccumulatedMicros()} as it is more precise. */ + @Deprecated @JsonIgnore public synchronized long getAccumulatedMillis() { - if (this.begin == 0) { - return 0; + return getAccumulatedMicros() / 1000; + } + + /** + * Return the total amount of time elapsed since start was called, if running, or + * difference between stop and start, in microseconds. + */ + @JsonIgnore + public synchronized long getAccumulatedMicros() { + if (this.durationMicros != null) { + return this.durationMicros; + } else { // stop() hasn't yet been called + if (this.begin == 0) { + return 0; + } + if (this.startNanos != null) { + return (System.nanoTime() - this.startNanos) / 1000; + } else { + return (System.currentTimeMillis() - this.begin) * 1000; + } } - if (this.end > 0) { - return this.end - this.begin; - } - return System.currentTimeMillis() - this.begin; } /** @@ -230,7 +270,7 @@ public class Span { */ @JsonIgnore public synchronized boolean isRunning() { - return this.begin != 0 && this.end == 0; + return this.begin != 0 && this.durationMicros == null; } /** @@ -430,6 +470,13 @@ public class Span { SpanBuilder() { } + /** + * Call this to record a begin time of a Span you didn't start. Don't call this when you are + * starting the span. + * + *

In other words, don't call {@code builder.begin(System.currentTimeMillis());}. doing so is + * redundant and will result in less precision when calculating elapsed time. + */ public Span.SpanBuilder begin(long begin) { this.begin = begin; return this; diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java index b4bb2821b..e1bc938b6 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java @@ -77,7 +77,7 @@ public class DefaultTracer implements Tracer { } else { long id = createId(); - span = Span.builder().begin(System.currentTimeMillis()).name(name).traceId(id) + span = Span.builder().name(name).traceId(id) .spanId(id).build(); if (sampler==null) { sampler = this.defaultSampler; @@ -141,7 +141,7 @@ public class DefaultTracer implements Tracer { protected Span createChild(Span parent, String name) { long id = createId(); if (parent == null) { - Span span = Span.builder().begin(System.currentTimeMillis()).name(name) + Span span = Span.builder().name(name) .traceId(id).spanId(id).build(); span = sampledSpan(name, id, span, this.defaultSampler); this.spanLogger.logStartedSpan(null, span); @@ -151,7 +151,7 @@ public class DefaultTracer implements Tracer { if (!isTracing()) { SpanContextHolder.push(parent, true); } - Span span = Span.builder().begin(System.currentTimeMillis()).name(name) + Span span = Span.builder().name(name) .traceId(parent.getTraceId()).parent(parent.getSpanId()).spanId(id) .processId(parent.getProcessId()).savedSpan(parent) .exportable(parent.isExportable()).build(); diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/SpanTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/SpanTests.java index c8eb2a071..1021a6213 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/SpanTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/SpanTests.java @@ -24,6 +24,7 @@ import com.fasterxml.jackson.databind.ObjectMapper; import org.junit.Test; +import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.api.BDDAssertions.then; /** @@ -114,4 +115,24 @@ public class SpanTests { public void should_throw_exception_when_converting_invalid_hex_value() { Span.hexToId("invalid"); } + + /** When going over a transport like spring-cloud-stream, we must retain the precise duration. */ + @Test public void shouldSerializeDurationMicros() throws IOException { + Span span = Span.builder().traceId(1L).name("http:parent").remote(true).build(); + span.stop(); + + assertThat(span.getAccumulatedMicros()) + .isGreaterThan(0L); // sanity check + + ObjectMapper objectMapper = new ObjectMapper(); + + String serialized = objectMapper.writeValueAsString(span); + assertThat(serialized) + .contains("\"durationMicros\""); + + Span deserialized = objectMapper.readValue(serialized, Span.class); + + assertThat(deserialized.getAccumulatedMicros()) + .isEqualTo(span.getAccumulatedMicros()); + } } 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 6d6da4ae2..b086c876f 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 @@ -90,7 +90,9 @@ final class ConvertToZipkinSpanList { ensureServerAddr(span, zipkinSpan, ep); } zipkinSpan.timestamp(span.getBegin() * 1000); - zipkinSpan.duration(span.getAccumulatedMillis() * 1000); + if (!span.isRunning()) { // duration is authoritative, only write when the span stopped + zipkinSpan.duration(span.getAccumulatedMicros()); + } zipkinSpan.traceId(span.getTraceId()); if (span.getParents().size() > 0) { if (span.getParents().size() > 1) { 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 ae04abac9..ff282ff70 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 @@ -108,6 +108,39 @@ public class ConvertToZipkinSpanListTests { .contains("barservice"); } + /** Sleuth timestamps are millisecond granularity while zipkin is microsecond. */ + @Test + public void convertsTimestampToMicrosecondsAndSetsDurationToAccumulatedMicros() { + long start = System.currentTimeMillis(); + Span span = span("foo"); + span.logEvent(Constants.CLIENT_SEND); + 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); + assertThat(result.duration) + .isEqualTo(span.getAccumulatedMicros()); + assertThat(result.annotations.get(0).timestamp) + .isGreaterThanOrEqualTo(start * 1000) + .isLessThanOrEqualTo(System.currentTimeMillis() * 1000); + } + + /** Zipkin's duration should only be set when the span is finished. */ + @Test + public void doesntSetDurationWhenStillRunning() { + Span running = Span.builder().traceId(1L).name("http:parent").remote(true).build(); + Spans spans = new Spans(this.host, Collections.singletonList(running)); + zipkin.Span result = ConvertToZipkinSpanList.convert(spans).get(0); + + assertThat(result.timestamp) + .isGreaterThan(0); // sanity check it did start + assertThat(result.duration) + .isNull(); + } + Span span(String name) { Long id = new Random().nextLong(); return new Span(1, 3, "message:" + name, id, Collections.emptyList(), id, true, true, 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 2fa339d3c..36858de6a 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 @@ -86,7 +86,9 @@ public class ZipkinSpanListener implements SpanReporter { ensureServerAddr(span, zipkinSpan); } zipkinSpan.timestamp(span.getBegin() * 1000L); - zipkinSpan.duration(span.getAccumulatedMillis() * 1000L); + if (!span.isRunning()) { // duration is authoritative, only write when the span stopped + zipkinSpan.duration(span.getAccumulatedMicros()); + } zipkinSpan.traceId(span.getTraceId()); if (span.getParents().size() > 0) { if (span.getParents().size() > 1) { 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 ad8630173..1b9a2cb4a 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 @@ -64,7 +64,7 @@ public class ZipkinSpanListenerTests { /** Sleuth timestamps are millisecond granularity while zipkin is microsecond. */ @Test - public void convertsTimestampAndDurationToMicroseconds() { + public void convertsTimestampToMicrosecondsAndSetsDurationToAccumulatedMicros() { long start = System.currentTimeMillis(); this.parent.logEvent("hystrix/retry"); // System.currentTimeMillis this.parent.stop(); @@ -74,12 +74,23 @@ public class ZipkinSpanListenerTests { assertThat(result.timestamp) .isEqualTo(this.parent.getBegin() * 1000); assertThat(result.duration) - .isEqualTo((this.parent.getEnd() - this.parent.getBegin()) * 1000); + .isEqualTo(this.parent.getAccumulatedMicros()); assertThat(result.annotations.get(0).timestamp) .isGreaterThanOrEqualTo(start * 1000) .isLessThanOrEqualTo(System.currentTimeMillis() * 1000); } + /** Zipkin's duration should only be set when the span is finished. */ + @Test + public void doesntSetDurationWhenStillRunning() { + zipkin.Span result = this.spanReporter.convert(this.parent); + + assertThat(result.timestamp) + .isGreaterThan(0); // sanity check it did start + assertThat(result.duration) + .isNull(); + } + /** Sleuth host corresponds to annotation/binaryAnnotation.host in zipkin. */ @Test public void annotationsIncludeHost() {