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

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/Span.java

@@ -145,6 +145,11 @@ public class Span {
 	private final List<Log> 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.<Long>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<Long> 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.
+		 *
+		 * <p>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;

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();

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());
+	}
 }

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) {

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.<Long>emptyList(), id, true, true,

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) {

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() {