Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

#13295: Instrumenter.getNanos() returns non-epoch timestamp. #13535

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
+43 −1
Open

#13295: Instrumenter.getNanos() returns non-epoch timestamp. #13535

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion ...ion-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -266,7 +266,7 @@ private void doEnd(

private static long getNanos(@Nullable Instant time) {
if (time == null) {
return System.nanoTime();
time = Instant.now();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

time measurements should use a monotonic time source, Instant.now is not monotonic

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is not a return statement. It is to replace the null input arguement with the same Instant object with current time, then goes to line 272 to calculate the a monotonic time.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think you have misunderstood what monotonic means here. The problem with using the "wall clock" time for like Instant.now for measuring elapsed time is that it is affected by system time adjustments. If system time is adjusted either by user or ntp between start or stop then stop can be before start which would result in a negative duration. Monotonic time only goes forward and is not adjusted.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If system time is adjusted either by user or ntp between start or stop, then your same argument applies to line 272, where the input argument time is not null. Are we saying that we should not use the input argument time as all? If so, the whole logic in this getNanos() should be changed accordingly.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since this is a private method it seems to be working correctly for the desired public and internal API behaviors. If it helps, maybe just add a comment This must be called for start/end times either both null or both non-null without other changes?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If system time is adjusted either by user or ntp between start or stop, then your same argument applies to line 272, where the input argument time is not null. Are we saying that we should not use the input argument time as all? If so, the whole logic in this getNanos() should be changed accordingly.

It would apply if both the start and end instances were constructed by calling Instant.now, but that is not what we do. Have a look at https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/internal/Timer.java

}
return TimeUnit.SECONDS.toNanos(time.getEpochSecond()) + time.getNano();
}
Expand Down
42 changes: 42 additions & 0 deletions ...api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/InstrumenterTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,20 +25,23 @@
import io.opentelemetry.context.Context;
import io.opentelemetry.context.ContextKey;
import io.opentelemetry.context.propagation.TextMapGetter;
import io.opentelemetry.instrumentation.api.internal.InstrumenterUtil;
import io.opentelemetry.instrumentation.api.internal.SchemaUrlProvider;
import io.opentelemetry.instrumentation.api.internal.SpanKey;
import io.opentelemetry.instrumentation.api.internal.SpanKeyProvider;
import io.opentelemetry.sdk.common.InstrumentationScopeInfo;
import io.opentelemetry.sdk.testing.junit5.OpenTelemetryExtension;
import io.opentelemetry.sdk.trace.data.LinkData;
import io.opentelemetry.sdk.trace.data.StatusData;
import java.time.Instant;
import java.util.Collections;
import java.util.HashMap;
import java.util.Map;
import java.util.concurrent.atomic.AtomicReference;
import java.util.stream.Collectors;
import java.util.stream.Stream;
import javax.annotation.Nullable;
import org.assertj.core.api.Assertions;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.ExtendWith;
import org.junit.jupiter.api.extension.RegisterExtension;
Expand Down Expand Up @@ -581,6 +584,45 @@ void instrumentationVersion_default() {
span -> span.hasName("span").hasInstrumentationScopeInfo(expectedLibraryInfo)));
}

@Test
void instrumenterGetNanosWithNullArgument() {
AtomicReference<Long> endTime = new AtomicReference<>();
OperationListener operationListener =
new OperationListener() {
@Override
public Context onStart(Context context, Attributes startAttributes, long startNanos) {
return context;
}

@Override
public void onEnd(Context context, Attributes endAttributes, long endNanos) {
endTime.set(endNanos);
}
};

InstrumenterBuilder<Map<String, String>, Map<String, String>> builder =
Instrumenter.builder(
otelTesting.getOpenTelemetry(), "test-instrumentation", name -> "span");
builder.addOperationListener(operationListener);
InstrumenterUtil.propagateOperationListenersToOnEnd(builder);

Instant startTime = Instant.now();
Instrumenter<Map<String, String>, Map<String, String>> instrumenter =
builder.buildInstrumenter();
InstrumenterUtil.startAndEnd(
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

startAndEnd doesn't have Nullable time parameters and is an internal method, so this seems invalid

instrumenter, Context.root(), emptyMap(), emptyMap(), null, startTime, null);

otelTesting
.assertTraces()
.hasTracesSatisfyingExactly(
trace ->
trace.hasSpansSatisfyingExactly(span -> span.hasName("span").startsAt(startTime)));
System.out.printf(
"Epoche second of start: %d and end: %d\n",
startTime.getEpochSecond(), endTime.get() / 1_000_000_000);
Assertions.assertThat(endTime.get() / 1_000_000_000 == startTime.getEpochSecond()).isTrue();
}

@Test
void instrumentationVersion_custom() {
Instrumenter<Map<String, String>, Map<String, String>> instrumenter =
Expand Down
Loading