Trace execution with ConsoleSpanExporter in Windows returns identical timestamps

[mchamlee]

Working with OpenTelemetry in Python for the first time today, seeing an odd issue where timestamps come out identical in most cases when running in a Windows Professional/Enterprise environment. I've seen some uniqueness in the timestamps rarely, and usually right after starting or restarting the Flask app, and only the first run after the restart.

Describe your environment
Windows 10 Enterprise 20H2 19042.2364 (VMware VDI) & Windows 11 Professional for Workstations 22H2 22621.963 (bare metal)
Python 3.8.10 && 3.9.13
Flask==2.2.2
opentelemetry-api==1.15.0
opentelemetry-sdk==1.15.0

Steps to reproduce
Primarily followed guide here: Tutorial on Timescale.com.

from random import randint
from flask import Flask, request

from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import (BatchSpanProcessor, ConsoleSpanExporter)

trace.set_tracer_provider(TracerProvider())
trace.get_tracer_provider().add_span_processor(
    BatchSpanProcessor(ConsoleSpanExporter())
)
tracer = trace.get_tracer(__name__)

app = Flask(__name__)


@app.route("/roll")
def roll():
    with tracer.start_as_current_span(
        "server_request",
        attributes={"endpoint": "/roll"}
    ):

        sides = int(request.args.get('sides'))
        rolls = int(request.args.get('rolls'))
        return roll_sum(sides, rolls)


def roll_sum(sides, rolls):
    span = trace.get_current_span()
    total = 0
    for r in range(0, rolls):
        result = randint(1, sides)
        span.add_event("log", {
            "roll.sides": sides,
            "roll.result": result,
        })
        total += result
    return str(total)

1. Start flask: flask run
2. In a browser or curl: http://127.0.0.1:5000/roll?sides=10&rolls=5
3. View output in console.

What is the expected behavior?
Expectation is to see unique timestamps across each recording in the output telemetry, parent and children. Expected output below is from the same code running on a RHEL8 server with Python 3.8.10.

{
    "name": "server_request",
    "context": {
        "trace_id": "0x79701fdaefb5c04219fbd1ee525d7ca1",
        "span_id": "0x7a1ccfac8fd5177d",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": null,
    "start_time": "2022-12-29T23:05:08.879293Z",
    "end_time": "2022-12-29T23:05:08.879470Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "endpoint": "/roll"
    },
    "events": [
        {
            "name": "log",
            "timestamp": "2022-12-29T23:05:08.879411Z",
            "attributes": {
                "roll.sides": 10,
                "roll.result": 10
            }
        },
        {
            "name": "log",
            "timestamp": "2022-12-29T23:05:08.879427Z",
            "attributes": {
                "roll.sides": 10,
                "roll.result": 8
            }
        },
        {
            "name": "log",
            "timestamp": "2022-12-29T23:05:08.879439Z",
            "attributes": {
                "roll.sides": 10,
                "roll.result": 9
            }
        },
        {
            "name": "log",
            "timestamp": "2022-12-29T23:05:08.879449Z",
            "attributes": {
                "roll.sides": 10,
                "roll.result": 3
            }
        },
        {
            "name": "log",
            "timestamp": "2022-12-29T23:05:08.879459Z",
            "attributes": {
                "roll.sides": 10,
                "roll.result": 3
            }
        }
    ],
    "links": [],
    "resource": {
        "attributes": {
            "telemetry.sdk.language": "python",
            "telemetry.sdk.name": "opentelemetry",
            "telemetry.sdk.version": "1.15.0",
            "service.name": "unknown_service"
        },
        "schema_url": ""
    }
}

What is the actual behavior?
When running this code in Windows, in about 90% of cases all timestamps are the same.

{
    "name": "server_request",
    "context": {
        "trace_id": "0x390a9c2d3f3daa9a6eca6f82d5bbb112",
        "span_id": "0x17451d6f7e56eef1",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": null,
    "start_time": "2022-12-29T23:14:47.350048Z",
    "end_time": "2022-12-29T23:14:47.350048Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "endpoint": "/roll"
    },
    "events": [
        {
            "name": "log",
            "timestamp": "2022-12-29T23:14:47.350048Z",
            "attributes": {
                "roll.sides": 10,
                "roll.result": 6
            }
        },
        {
            "name": "log",
            "timestamp": "2022-12-29T23:14:47.350048Z",
            "attributes": {
                "roll.sides": 10,
                "roll.result": 2
            }
        },
        {
            "name": "log",
            "timestamp": "2022-12-29T23:14:47.350048Z",
            "attributes": {
                "roll.sides": 10,
                "roll.result": 8
            }
        },
        {
            "name": "log",
            "timestamp": "2022-12-29T23:14:47.350048Z",
            "attributes": {
                "roll.sides": 10,
                "roll.result": 10
            }
        },
        {
            "name": "log",
            "timestamp": "2022-12-29T23:14:47.350048Z",
            "attributes": {
                "roll.sides": 10,
                "roll.result": 2
            }
        }
    ],
    "links": [],
    "resource": {
        "attributes": {
            "telemetry.sdk.language": "python",
            "telemetry.sdk.name": "opentelemetry",
            "telemetry.sdk.version": "1.15.0",
            "service.name": "unknown_service"
        },
        "schema_url": ""
    }
}

Additional context
Add any other context about the problem here.

[ocelotl]

Hello, sorry for the late reply.

We use time_ns for our timestamps. I see that there is a significant difference between Linux and Windows resolutions for time_ns, the Linux one being much higher. I think this behavior could an unavoidable consequence of the lower Windows time_ns resoluiton.

[mchamlee]

No problem @ocelotl , appreciate the reply nonetheless. While I think there is value in correcting this, if at all possible, I've advised our teams for now that they'll need to develop solutions in WSL if on Windows, else macOS.

[ocelotl]

I'll close this issue now, @mchamlee, please reopen if there is something else we can help with.