SpringCloud/spring-cloud-sleuth
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Updating the duration setting (#360)

Browse Source 
* Updating the duration setting

fixes #349
This commit is contained in:
Marcin Grzejszczak
2016-07-29 23:29:31 +02:00
committed by GitHub
parent f74dafbda6
commit 11e520c70d
5 changed files with 105 additions and 3 deletions
Download Patch File Download Diff File Expand all files Collapse all files

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

@@ -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

28
spring-cloud-sleuth-zipkin-stream/src/main/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanList.java
View File

@@ -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;
}
}

24
spring-cloud-sleuth-zipkin-stream/src/test/java/org/springframework/cloud/sleuth/zipkin/stream/ConvertToZipkinSpanListTests.java
View File

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

29
spring-cloud-sleuth-zipkin/src/main/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListener.java
View File

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

23
spring-cloud-sleuth-zipkin/src/test/java/org/springframework/cloud/sleuth/zipkin/ZipkinSpanListenerTests.java
View File

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