Span start_time has reduced timing resolution when mapped to Timestamp proto

[michael-booth]

Issue:

Our team has started integrating python Lightstep support within aiohttp (asyncio) services.
We noticed when doing cross language traces that the python generated span timelines were skewed compared to other spans emitted in the same trace

Span start times as reported in Lightstep UI are always truncated to the second. This is visible when observing the microseconds stamp in Lightstep UI (see below). Note the trailing 000000.

Digging into the Lightstep code, I believe is due to the following code line in http_converter.py

start_timestamp=Timestamp(seconds=int(span.start_time)),

Which casts the span.start_time (float) to the second (int) and sets it on the Timestamp object.
Since spans sent via proto are now shifted to the second, the resulting finish time (which appears to be calculated start_time + duration) are marked as finishing earlier than they actually did.
The result of this was we saw spans emitted by downstream traced services appear later in the trace timeline than the parent calling span in python

Potential Solution:

Looking at the google docs on Timestamp, it appears we can supply both the seconds and nanos as a parameter to the object. An example can be found here:

now = time.time()
seconds = int(now)
nanos = int((now - seconds) * 10**9)
timestamp = Timestamp(seconds=seconds, nanos=nanos)

After locally applying the suggested code to the http_converter.py, traces emitted now appear to have the correct resolution.

Setup:

python==3.6.6
opentracing==2.0.0
lightstep==4.0.0
googleapis-common-protos==1.5.3

Can you confirm this is unintentional behaviour and whether our proposed solution would be accepted?

Thanks

[carlosalberto]

Hey @michael-booth

Thanks for the report. Indeed, it looks like we could add the nanos part to have better resolution. Anything against doing this @frenchfrywpepper ?

[frenchfrywpepper]

Nope, seems smart.

[michael-booth]

Given that this is a fairly small amendment - i'm happy to open a PR for the proposed change if that is of help?

[carlosalberto]

@frenchfrywpepper Thanks!

@michael-booth Please do!

[michael-booth]

thanks for the speedy replies all 👍 - PR opened.

[carlosalberto]

@michael-booth It should be fixed (and released) by now. Let us know upon confirmation ;)

[michael-booth]

HI @carlosalberto - just pulled the new release and run in our test service. Traces have the correct resolution on timestamps now and look good in the Lightstep UI 👍

[carlosalberto]

Closing this issue. Thanks!