From 9eef58720fda56875b69bcd42e90e2968a95923b Mon Sep 17 00:00:00 2001 From: Adrian Cole Date: Mon, 21 Mar 2016 12:34:38 +0800 Subject: [PATCH] Ports remaining scala SpanStoreSpec tests to SpanStoreTest This ports remaining tests to java, and also ports code changes needed to make them pass. --- .../main/java/zipkin/jdbc/JDBCSpanStore.java | 8 +- .../internal/ApplyTimestampAndDuration.java | 49 ++++----- .../src/test/java/zipkin/SpanStoreTest.java | 102 +++++++++++++----- 3 files changed, 102 insertions(+), 57 deletions(-) diff --git a/zipkin-spanstores/jdbc/src/main/java/zipkin/jdbc/JDBCSpanStore.java b/zipkin-spanstores/jdbc/src/main/java/zipkin/jdbc/JDBCSpanStore.java index 227f9a25302..3f679703c51 100644 --- a/zipkin-spanstores/jdbc/src/main/java/zipkin/jdbc/JDBCSpanStore.java +++ b/zipkin-spanstores/jdbc/src/main/java/zipkin/jdbc/JDBCSpanStore.java @@ -99,6 +99,7 @@ public void accept(List spans) { List inserts = new ArrayList<>(); for (Span span : spans) { + Long authoritativeTimestamp = span.timestamp; span = ApplyTimestampAndDuration.apply(span); Long binaryAnnotationTimestamp = span.timestamp; if (binaryAnnotationTimestamp == null) { // fallback if we have no timestamp, yet @@ -109,8 +110,8 @@ public void accept(List spans) { if (!span.name.equals("") && !span.name.equals("unknown")) { updateFields.put(ZIPKIN_SPANS.NAME, span.name); } - if (span.timestamp != null) { - updateFields.put(ZIPKIN_SPANS.START_TS, span.timestamp); + if (authoritativeTimestamp != null) { + updateFields.put(ZIPKIN_SPANS.START_TS, authoritativeTimestamp); } if (span.duration != null) { updateFields.put(ZIPKIN_SPANS.DURATION, span.duration); @@ -229,7 +230,8 @@ List> getTraces(@Nullable QueryRequest request, @Nullable Long traceI } } } - trace.add(span.build()); + Span rawSpan = span.build(); + trace.add(raw ? rawSpan : ApplyTimestampAndDuration.apply(rawSpan)); } if (!raw) trace = CorrectForClockSkew.apply(trace); result.add(trace); diff --git a/zipkin/src/main/java/zipkin/internal/ApplyTimestampAndDuration.java b/zipkin/src/main/java/zipkin/internal/ApplyTimestampAndDuration.java index 54e44fddfa7..2ef2e19c59c 100644 --- a/zipkin/src/main/java/zipkin/internal/ApplyTimestampAndDuration.java +++ b/zipkin/src/main/java/zipkin/internal/ApplyTimestampAndDuration.java @@ -13,7 +13,6 @@ */ package zipkin.internal; -import java.util.List; import zipkin.Annotation; import zipkin.Constants; import zipkin.Span; @@ -30,39 +29,33 @@ public class ApplyTimestampAndDuration { // For spans that core client annotations, the distance between "cs" and "cr" should be the // authoritative duration. We are special-casing this to avoid setting incorrect duration // when there's skew between the client and the server. - public static Span apply(Span s) { - if ((s.timestamp == null || s.duration == null) && !s.annotations.isEmpty()) { - Long ts = s.timestamp; - Long dur = s.duration; - ts = ts != null ? ts : getFirstTimestamp(s.annotations); - if (dur == null) { - long lastTs = getLastTimestamp(s.annotations); - if (ts != lastTs) { - dur = lastTs - ts; - } - } - return new Span.Builder(s).timestamp(ts).duration(dur).build(); + public static Span apply(Span span) { + // Don't overwrite authoritatively set timestamp and duration! + if (span.timestamp != null && span.duration != null) { + return span; } - return s; - } - static long getFirstTimestamp(List annotations) { - for (int i = 0, length = annotations.size(); i < length; i++) { - if (annotations.get(i).value.equals(Constants.CLIENT_SEND)) { - return annotations.get(i).timestamp; - } + // Only calculate span.timestamp and duration on complete spans. This avoids + // persisting an inaccurate timestamp due to a late arriving annotation. + if (span.annotations.size() < 2) { + return span; } - return annotations.get(0).timestamp; - } - static long getLastTimestamp(List annotations) { - int length = annotations.size(); - for (int i = 0; i < length; i++) { - if (annotations.get(i).value.equals(Constants.CLIENT_RECV)) { - return annotations.get(i).timestamp; + // For spans that core client annotations, the distance between "cs" and "cr" should be the + // authoritative duration. We are special-casing this to avoid setting incorrect duration + // when there's skew between the client and the server. + Long first = span.annotations.get(0).timestamp; + Long last = span.annotations.get(span.annotations.size() - 1).timestamp; + for (Annotation annotation : span.annotations) { + if (annotation.value.equals(Constants.CLIENT_SEND)) { + first = annotation.timestamp; + } else if (annotation.value.equals(Constants.CLIENT_RECV)) { + last = annotation.timestamp; } } - return annotations.get(length - 1).timestamp; + long ts = span.timestamp != null ? span.timestamp : first; + Long dur = span.duration != null ? span.duration : last.equals(first) ? null : last - first; + return new Span.Builder(span).timestamp(ts).duration(dur).build(); } private ApplyTimestampAndDuration() { diff --git a/zipkin/src/test/java/zipkin/SpanStoreTest.java b/zipkin/src/test/java/zipkin/SpanStoreTest.java index 0c9eb6431a4..c4f002ac2cf 100644 --- a/zipkin/src/test/java/zipkin/SpanStoreTest.java +++ b/zipkin/src/test/java/zipkin/SpanStoreTest.java @@ -25,7 +25,11 @@ import static java.util.Arrays.asList; import static java.util.Collections.emptyList; import static org.assertj.core.api.Assertions.assertThat; +import static zipkin.Constants.CLIENT_RECV; +import static zipkin.Constants.CLIENT_SEND; import static zipkin.Constants.LOCAL_COMPONENT; +import static zipkin.Constants.SERVER_RECV; +import static zipkin.Constants.SERVER_SEND; /** * Base test for {@link SpanStore} implementations. Subtypes should create a connection to a real @@ -458,10 +462,10 @@ public void correctsClockSkew() { .traceId(1) .name("method1") .id(666) - .addAnnotation(Annotation.create((today + 100) * 1000, Constants.CLIENT_SEND, client)) - .addAnnotation(Annotation.create((today + 95) * 1000, Constants.SERVER_RECV, frontend)) // before client sends - .addAnnotation(Annotation.create((today + 120) * 1000, Constants.SERVER_SEND, frontend)) // before client receives - .addAnnotation(Annotation.create((today + 135) * 1000, Constants.CLIENT_RECV, client)).build(); + .addAnnotation(Annotation.create((today + 100) * 1000, CLIENT_SEND, client)) + .addAnnotation(Annotation.create((today + 95) * 1000, SERVER_RECV, frontend)) // before client sends + .addAnnotation(Annotation.create((today + 120) * 1000, SERVER_SEND, frontend)) // before client receives + .addAnnotation(Annotation.create((today + 135) * 1000, CLIENT_RECV, client)).build(); /** Intentionally not setting span.timestamp, duration */ Span remoteChild = new Span.Builder() @@ -469,10 +473,10 @@ public void correctsClockSkew() { .name("method2") .id(777) .parentId(666L) - .addAnnotation(Annotation.create((today + 100) * 1000, Constants.CLIENT_SEND, frontend)) - .addAnnotation(Annotation.create((today + 115) * 1000, Constants.SERVER_RECV, backend)) - .addAnnotation(Annotation.create((today + 120) * 1000, Constants.SERVER_SEND, backend)) - .addAnnotation(Annotation.create((today + 115) * 1000, Constants.CLIENT_RECV, frontend)) // before server sent + .addAnnotation(Annotation.create((today + 100) * 1000, CLIENT_SEND, frontend)) + .addAnnotation(Annotation.create((today + 115) * 1000, SERVER_RECV, backend)) + .addAnnotation(Annotation.create((today + 120) * 1000, SERVER_SEND, backend)) + .addAnnotation(Annotation.create((today + 115) * 1000, CLIENT_RECV, frontend)) // before server sent .build(); /** Local spans must explicitly set timestamp */ @@ -510,31 +514,77 @@ public void correctsClockSkew() { assertThat(adjusted.get(2).duration).isEqualTo(skewed.get(2).duration); } + /** + * This test shows that regardless of whether span.timestamp and duration are set directly or + * derived from annotations, the client wins vs the server. This is important because the client + * holds the critical path of a shared span. + */ @Test - public void rawTrace(){ + public void clientTimestampAndDurationWinInSharedSpan() { Endpoint client = Endpoint.create("client", 192 << 24 | 168 << 16 | 1, 8080); + Endpoint server = Endpoint.create("server", 192 << 24 | 168 << 16 | 2, 8080); + + long clientTimestamp = (today + 100) * 1000; + long clientDuration = 35 * 1000; + + // both client and server set span.timestamp, duration + Span clientView = new Span.Builder().traceId(1).name("direct").id(666) + .timestamp(clientTimestamp).duration(clientDuration) + .addAnnotation(Annotation.create((today + 100) * 1000, CLIENT_SEND, client)) + .addAnnotation(Annotation.create((today + 135) * 1000, CLIENT_RECV, client)) + .build(); + + Span serverView = new Span.Builder().traceId(1).name("direct").id(666) + .timestamp((today + 105) * 1000).duration(25 * 1000L) + .addAnnotation(Annotation.create((today + 105) * 1000, SERVER_RECV, server)) + .addAnnotation(Annotation.create((today + 130) * 1000, SERVER_SEND, server)) + .build(); + + // neither client, nor server set span.timestamp, duration + Span clientViewDerived = new Span.Builder().traceId(1).name("derived").id(666) + .addAnnotation(Annotation.create(clientTimestamp, CLIENT_SEND, client)) + .addAnnotation(Annotation.create(clientTimestamp + clientDuration, CLIENT_SEND, client)) + .build(); + + Span serverViewDerived = new Span.Builder().traceId(1).name("derived").id(666) + .addAnnotation(Annotation.create((today + 105) * 1000, SERVER_RECV, server)) + .addAnnotation(Annotation.create((today + 130) * 1000, SERVER_SEND, server)) + .build(); + + store.accept(asList(serverView, serverViewDerived)); // server span hits the collection tier first + store.accept(asList(clientView, clientViewDerived)); // intentionally different collection event + + for (Span span : store.getTrace(clientView.traceId)) { + assertThat(span.timestamp).isEqualTo(clientTimestamp); + assertThat(span.duration).isEqualTo(clientDuration); + } + } + + // This supports the "raw trace" feature, which skips application-level data cleaning + @Test + public void rawTrace_doesntPerformQueryTimeAdjustment() { Endpoint frontend = Endpoint.create("frontend", 192 << 24 | 168 << 16 | 2, 8080); + Annotation sr = Annotation.create((today + 95) * 1000, SERVER_RECV, frontend); + Annotation ss = Annotation.create((today + 100) * 1000, SERVER_SEND, frontend); - Span span = new Span.Builder() - .traceId(1) - .name("method1") - .id(666) - .timestamp((today + 95) * 1000) - .duration(20 * 1000L) - .addAnnotation(Annotation.create((today + 100) * 1000, Constants.CLIENT_SEND, client)) - .addAnnotation(Annotation.create((today + 95) * 1000, Constants.SERVER_RECV, frontend)) // before client sends - .addAnnotation(Annotation.create((today + 120) * 1000, Constants.SERVER_SEND, frontend)) // before client receives - .addAnnotation(Annotation.create((today + 135) * 1000, Constants.CLIENT_RECV, client)).build(); + Span span = new Span.Builder().traceId(1).name("method1").id(666).build(); - store.accept(asList(span)); + // Simulate instrumentation that sends annotations one at-a-time. + // This should prevent the collection tier from being able to calculate duration. + store.accept(asList(new Span.Builder(span).addAnnotation(sr).build())); + store.accept(asList(new Span.Builder(span).addAnnotation(ss).build())); - // clock skew adjustment will affect the span returned by default + // Normally, span store implementations will merge spans by id and add duration by query time assertThat(store.getTrace(span.traceId)) - .doesNotContain(span); - - // the raw trace does not include any adjustments at query time, such as clock skew - assertThat(store.getRawTrace(span.traceId)) - .containsExactly(span); + .containsExactly(new Span.Builder(span) + .timestamp(sr.timestamp) + .duration(ss.timestamp - sr.timestamp) + .annotations(asList(sr, ss)).build()); + + // Since a collector never saw both sides of the span, we'd not see duration in the raw trace. + for (Span raw : store.getRawTrace(span.traceId)) { + assertThat(raw.duration).isNull(); + } } static long clientDuration(Span span) {