From 3c3766aaca850647dfdf2292c709a438cbf9c9a5 Mon Sep 17 00:00:00 2001 From: Johannes Liebermann Date: Wed, 9 Oct 2019 18:29:01 +0200 Subject: [PATCH] Handle inaccuracies in time conversions Due to the differences between decimal and binary float representations, some time values yield "suprising" results when performing float arithmetic operations to convert seconds to nanoseconds and vice versa. --- .../src/opentracingshim/__init__.py | 8 ++++--- opentracing-shim/tests/test_shim.py | 24 +++++++++++++++---- opentracing-shim/tests/test_util.py | 15 ++++++++++++ 3 files changed, 40 insertions(+), 7 deletions(-) diff --git a/opentracing-shim/src/opentracingshim/__init__.py b/opentracing-shim/src/opentracingshim/__init__.py index ca277cccecc..a57b84abe29 100644 --- a/opentracing-shim/src/opentracingshim/__init__.py +++ b/opentracing-shim/src/opentracingshim/__init__.py @@ -68,11 +68,13 @@ def set_tag(self, key, value): return self def log_kv(self, key_values, timestamp=None): - if timestamp is None: - timestamp = util.time_ns() + if timestamp is not None: + event_timestamp = util.time_seconds_to_ns(timestamp) + else: + event_timestamp = util.time_ns() event_name = util.event_name_from_kv(key_values) - event = Event(event_name, timestamp, key_values) + event = Event(event_name, event_timestamp, key_values) self._otel_span.add_lazy_event(event) # Return self for call chaining. diff --git a/opentracing-shim/tests/test_shim.py b/opentracing-shim/tests/test_shim.py index 87e5b4b78cd..d1bcdb79d67 100644 --- a/opentracing-shim/tests/test_shim.py +++ b/opentracing-shim/tests/test_shim.py @@ -118,7 +118,11 @@ def test_explicit_start_time(self): now = time.time() with self.shim.start_active_span("TestSpan", start_time=now) as scope: result = util.time_seconds_from_ns(scope.span.unwrap().start_time) - self.assertEqual(result, now) + # Tolerate inaccuracies of less than a microsecond. + # TODO: Put a link to an explanation in the docs. + # TODO: This seems to work consistently, but we should find out the + # biggest possible loss of precision. + self.assertAlmostEqual(result, now, places=6) def test_explicit_end_time(self): """Test `end_time` argument of `finish()` method.""" @@ -128,7 +132,11 @@ def test_explicit_end_time(self): span.finish(now) end_time = util.time_seconds_from_ns(span.unwrap().end_time) - self.assertEqual(end_time, now) + # Tolerate inaccuracies of less than a microsecond. + # TODO: Put a link to an explanation in the docs. + # TODO: This seems to work consistently, but we should find out the + # biggest possible loss of precision. + self.assertAlmostEqual(end_time, now, places=6) def test_explicit_span_activation(self): """Test manual activation and deactivation of a span.""" @@ -355,9 +363,17 @@ def test_log_kv(self): self.assertIsNotNone(span.unwrap().events[0].timestamp) # Test explicit timestamp. - now = opentracingshim.util.time_ns() + now = time.time() span.log_kv({"foo": "bar"}, now) - self.assertEqual(span.unwrap().events[1].timestamp, now) + result = util.time_seconds_from_ns( + span.unwrap().events[1].timestamp + ) + self.assertEqual(span.unwrap().events[1].attributes["foo"], "bar") + # Tolerate inaccuracies of less than a microsecond. + # TODO: Put a link to an explanation in the docs. + # TODO: This seems to work consistently, but we should find out the + # biggest possible loss of precision. + self.assertAlmostEqual(result, now, places=6) def test_span_context(self): """Test construction of `SpanContextWrapper` objects.""" diff --git a/opentracing-shim/tests/test_util.py b/opentracing-shim/tests/test_util.py index 99e0b61ddce..869164eef1e 100644 --- a/opentracing-shim/tests/test_util.py +++ b/opentracing-shim/tests/test_util.py @@ -48,3 +48,18 @@ def test_time_seconds_from_ns(self): result = util.time_seconds_from_ns(time_nanoseconds) self.assertEqual(result, time_nanoseconds / 1e9) + + def test_time_conversion_precision(self): + """Verify time conversion from seconds to nanoseconds and vice versa is + accurate enough. + """ + + time_seconds = 1570484241.9501917 + time_nanoseconds = util.time_seconds_to_ns(time_seconds) + result = util.time_seconds_from_ns(time_nanoseconds) + + # Tolerate inaccuracies of less than a microsecond. + # TODO: Put a link to an explanation in the docs. + # TODO: This seems to work consistently, but we should find out the + # biggest possible loss of precision. + self.assertAlmostEqual(result, time_seconds, places=6)