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 29b8a0d59..522493b76 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 @@ -190,7 +190,7 @@ public class Span { this.startNanos = null; // don't know the start tick this.begin = begin; } else { - this.startNanos = System.nanoTime(); + this.startNanos = nanoTime(); this.begin = System.currentTimeMillis(); } if (end > 0) { @@ -226,7 +226,7 @@ public class Span { this.end = System.currentTimeMillis(); } if (this.startNanos != null) { // set a precise duration - this.durationMicros = (System.nanoTime() - this.startNanos) / 1000; + this.durationMicros = Math.max(1, (nanoTime() - this.startNanos) / 1000); } else { this.durationMicros = (this.end - this.begin) * 1000; } @@ -248,6 +248,8 @@ public class Span { /** * Return the total amount of time elapsed since start was called, if running, or * difference between stop and start, in microseconds. + * + * @return zero if not running, or a positive number of microseconds. */ @JsonIgnore public synchronized long getAccumulatedMicros() { @@ -258,13 +260,19 @@ public class Span { return 0; } if (this.startNanos != null) { - return (System.nanoTime() - this.startNanos) / 1000; + return Math.max(1, (nanoTime() - this.startNanos) / 1000); } else { return (System.currentTimeMillis() - this.begin) * 1000; } } } + // Visible for testing + @JsonIgnore + long nanoTime() { + return System.nanoTime(); + } + /** * Has the span been started and not yet stopped? */ 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 1021a6213..8f80bc15a 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 @@ -18,6 +18,7 @@ package org.springframework.cloud.sleuth; import java.io.IOException; import java.util.Collections; +import java.util.concurrent.atomic.AtomicLong; import com.fasterxml.jackson.core.JsonProcessingException; import com.fasterxml.jackson.databind.ObjectMapper; @@ -135,4 +136,43 @@ public class SpanTests { assertThat(deserialized.getAccumulatedMicros()) .isEqualTo(span.getAccumulatedMicros()); } + + // Duration of 0 is confusing to plot and can be misinterpreted as null + @Test public void getAccumulatedMicros_roundsUpToOneWhenRunning() throws IOException { + AtomicLong nanoTime = new AtomicLong(); + + // starts the span, recording its initial tick as zero + Span span = new Span(0, 0, "http:name", 1L, Collections.emptyList(), 2L, true, + true, "process", null) { + @Override long nanoTime() { + return nanoTime.get(); + } + }; + + // When only 100 nanoseconds passed + nanoTime.set(100L); + + // We round so that we don't confuse "not started" with a short span. + assertThat(span.getAccumulatedMicros()).isEqualTo(1L); + } + + // Duration of 0 is confusing to plot and can be misinterpreted as null + @Test public void getAccumulatedMicros_roundsUpToOneWhenStopped() throws IOException { + AtomicLong nanoTime = new AtomicLong(); + + // starts the span, recording its initial tick as zero + Span span = new Span(0, 0, "http:name", 1L, Collections.emptyList(), 2L, true, + true, "process", null) { + @Override long nanoTime() { + return nanoTime.get(); + } + }; + + // When only 100 nanoseconds passed + nanoTime.set(100L); + span.stop(); + + // We round so that we don't confuse "not started" with a short span. + assertThat(span.getAccumulatedMicros()).isEqualTo(1L); + } } diff --git a/spring-cloud-sleuth-dependencies/pom.xml b/spring-cloud-sleuth-dependencies/pom.xml index 585448591..3e1c80af7 100644 --- a/spring-cloud-sleuth-dependencies/pom.xml +++ b/spring-cloud-sleuth-dependencies/pom.xml @@ -16,7 +16,7 @@ 1.2.0.BUILD-SNAPSHOT 1.8.4 - 1.1.5 + 1.3.0 diff --git a/spring-cloud-sleuth-samples/pom.xml b/spring-cloud-sleuth-samples/pom.xml index 65e702ae6..9da6ef988 100644 --- a/spring-cloud-sleuth-samples/pom.xml +++ b/spring-cloud-sleuth-samples/pom.xml @@ -59,12 +59,12 @@ io.zipkin.java zipkin - 1.1.5 + 1.3.0 io.zipkin.java zipkin-server - 1.1.5 + 1.3.0