Instrumenter.getNanos() returns non-epoch timestamp.

[wdengw]

Describe the bug

Instrumenter.getNanos() at line number 269 returns System.nanoTime() which is not a valid epoch timestamp. Should we consider to use

		time = Instant.now();

to replace it?

Steps to reproduce

The difference between the two can be seen by System.print(...) both returned times.

Expected behavior

The Instrumenter.getNanos() should return epoch timestamp.

Actual behavior

The Instrumenter.getNanos() returns non epoch timestamp.

Javaagent or library instrumentation version

The current version on main.

Environment

JDK:
OS:

Additional context

No response

[trask]

hi @wdengw! this is intentional, and should only be used to measure duration (against other calls to System.nanoTime)

is there a specific problem this is causing for you?

it does look like we pass this value to OperationListeners, and probably should make clear that this isn't a "timestamp" as the OperationListener javadoc seems to suggest:

https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/OperationListener.java#L25

[wdengw]

Hi, @trask If the getNanos() method is intended to return System.nanoTime() then line 271 is wrong. When this method returns the right epoch time, the span event display right information on Jaeger trace viewer. When this method returns System.nanoTime(). the number showed on Jaeger is wrong.

[trask]

span event display right information on Jaeger trace viewer

getNanos() is only used for passing to OperationListener (for capturing metric durations), can you provide a bit more context on how this is ending up on your spans?

[wdengw]

We followed the same logic to implement our tracing instrumentation. When calling Span.addEvent() method to add an event, we passed in the timestamp created from a similar getNanos() method. That led us to discover this discrepancy.

[laurit]

We followed the same logic to implement our tracing instrumentation. When calling Span.addEvent() method to add an event, we passed in the timestamp created from a similar getNanos() method. That led us to discover this discrepancy.

Just because System.nanoTime() wasn't suitable for usage does not mean that it is not suitable for our usage. Unlike Instant.now() System.nanoTime() provides monotonic time. For measuring duration a monotonic time source is desirable. Also consider that in jdk8 Instant.now() does not provide sub millisecond accuracy which makes it unsuitable for measuring short durations.

[github-actions]

This has been automatically marked as stale because it has been marked as needing author feedback and has not had any activity for 7 days. It will be closed automatically if there is no response from the author within 7 additional days from this comment.

[wdengw]

@laurit and @trask, Instrumenter.getNanos() is called in two places: Instrumenter.doStart() and Instrumenter.doEnd(). If a span is started by calling Instrumenter.doStart() with a null startTime argument and is ended by calling Instrumenter.doEnd() with a non-null endTime argument, the calculated duration for this span will be incorrect.

Here is the test code to demonstrate the calculated durations:

		Instant now = Instant.now();
		long systemNow = System.nanoTime();
		long getNanosNow = getNanos(null);
		Thread.sleep(500);
		System.out.printf("Duration calculated from System time: %d\n", System.nanoTime() - systemNow );
		long durationFromInstant = Instant.now().getNano() - now.getNano();
		System.out.printf("Duration calculated from Instant: %d\n", durationFromInstant < 0 ? 1000000000 + durationFromInstant : durationFromInstant);
		System.out.printf("Duration calculated from getNanos: %d\n", getNanos(Instant.now()) - getNanosNow);

Following is the outputs

Duration calculated from System time: 505145583
Duration calculated from Instant: 509245000
Duration calculated from getNanos: 1740157730710828792