Fix duration casts (#151)

Do not assume that the underlying clock precision is nanoseconds. Use
regex to match timestamps in unit test to avoid inherent fp precision
differences.

Fixes: #148

layer/support/layer_utils.h

@@ -85,6 +85,22 @@ TimestampClock::time_point GetTimestamp();
 // Returns a monotonic time_point to be used for measuring duration.
 DurationClock::time_point Now();
 
+namespace detail {
+template <typename DurationT>
+double DurationToMilliseconds(const DurationT& duration) {
+  using Millis =
+      std::chrono::duration<double, std::chrono::milliseconds::period>;
+  return std::chrono::duration_cast<Millis>(duration).count();
+}
+
+template <typename DurationT>
+int64_t DurationToNanoseconds(const DurationT& duration) {
+  using Nanos =
+      std::chrono::duration<int64_t, std::chrono::nanoseconds::period>;
+  return std::chrono::duration_cast<Nanos>(duration).count();
+}
+}  // namespace detail
+
 // A wrapper around `DurationClock::duration` to keep track of the time unit.
 // When the `Duration` is used, we know it's either created from a
 // `DurationClock::duration` that has nanosecond-level precision or an int that
@@ -94,7 +110,7 @@ class Duration {
   static Duration Min() { return DurationClock::duration::min(); }
 
   static Duration FromNanoseconds(int64_t nanos) {
-    return Duration(DurationClock::duration(nanos));
+    return std::chrono::nanoseconds(nanos);
   }
 
   Duration(DurationClock::duration duration) : duration_{duration} {}
@@ -116,11 +132,11 @@ class Duration {
   }
 
   int64_t ToNanoseconds() const {
-    return std::chrono::nanoseconds(duration_).count();
+    return detail::DurationToNanoseconds(duration_);
   }
 
   double ToMilliseconds() const {
-    return std::chrono::duration<double, std::milli>(duration_).count();
+    return detail::DurationToMilliseconds(duration_);
   }
 
  private:
@@ -137,27 +153,29 @@ class Timestamp {
   // has no epoch information. To create a time_point from it, it should be
   // converted into a duration representing the offset from the zero epoch.
   static Timestamp FromNanoseconds(int64_t nanos) {
-    return Timestamp(
-        TimestampClock::time_point(TimestampClock::duration(nanos)));
+    std::chrono::duration<int64_t, std::chrono::nanoseconds::period> dur(nanos);
+    return {
+        GetCanonicalEpoch() +
+        std::chrono::duration_cast<TimestampClock::time_point::duration>(dur)};
   }
 
   Timestamp(TimestampClock::time_point timestamp) : timestamp_{timestamp} {}
 
   int64_t ToNanoseconds() const {
-    return std::chrono::nanoseconds(timestamp_.time_since_epoch()).count();
+    return detail::DurationToNanoseconds(timestamp_ - GetCanonicalEpoch());
   }
 
   double ToMilliseconds() const {
-    return std::chrono::duration<double, std::milli>(
-               timestamp_.time_since_epoch())
-        .count();
+    return detail::DurationToMilliseconds(timestamp_ - GetCanonicalEpoch());
   }
 
   Timestamp operator-(const Duration& duration) {
-    return timestamp_ - TimestampClock::duration(duration.ToNanoseconds());
+    return FromNanoseconds(ToNanoseconds() - duration.ToNanoseconds());
   }
 
  private:
+  static TimestampClock::time_point GetCanonicalEpoch() { return {}; }
+
   TimestampClock::time_point timestamp_;
 };
 

layer/unittest/layer_utils_tests.cc

@@ -0,0 +1,42 @@
+// Copyright 2022 Google LLC
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//      http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include "gtest/gtest.h"
+#include "layer/support/layer_utils.h"
+
+namespace performancelayers {
+namespace {
+
+TEST(LayerUtils, DurationUnits) {
+  static constexpr double epsilon = 0.000001;
+  auto start = Timestamp::FromNanoseconds(1'000'000'000);
+  EXPECT_EQ(start.ToNanoseconds(), 1'000'000'000);
+  EXPECT_NEAR(start.ToMilliseconds(), 1000.0, epsilon);
+
+  Duration dur = Duration::FromNanoseconds(1000);
+  EXPECT_EQ(dur.ToNanoseconds(), 1000);
+  EXPECT_NEAR(dur.ToMilliseconds(), 0.001, epsilon);
+
+  auto end =
+      Timestamp::FromNanoseconds(start.ToNanoseconds() + dur.ToNanoseconds());
+  EXPECT_EQ(end.ToNanoseconds(), 1'000'001'000);
+  EXPECT_NEAR(end.ToMilliseconds(), 1000.001, epsilon);
+
+  Timestamp newStart = end - dur;
+  EXPECT_EQ(newStart.ToNanoseconds(), 1'000'000'000);
+  EXPECT_NEAR(newStart.ToMilliseconds(), 1000.0, epsilon);
+}
+
+}  // namespace
+}  // namespace performancelayers

layer/unittest/trace_event_log_tests.cc

@@ -24,6 +24,7 @@
 #include "layer/support/trace_event_logging.h"
 
 using ::testing::ElementsAre;
+using ::testing::MatchesRegex;
 
 namespace performancelayers {
 namespace {
@@ -195,8 +196,9 @@ TEST(TraceEvent, InstantEventToString) {
   InstantEvent instant_event("compile_time_init", kTestEventTimestamp,
                              "compile_time", 123, 321);
   std::string_view expected_str =
-      R"({ "name" : "compile_time_init", "ph" : "i", "cat" : "compile_time", "pid" : 123, "tid" : 321, "ts" : 0.001401, "s" : "g", "args" : { "scope" : "g" } },)";
-  EXPECT_EQ(EventToTraceEventString(instant_event), expected_str);
+      R"(\{ "name" : "compile_time_init", "ph" : "i", "cat" : "compile_time", "pid" : 123, "tid" : 321, "ts" : ([0-9\.]+), "s" : "g", "args" : \{ "scope" : "g" \} \},)";
+  EXPECT_THAT(EventToTraceEventString(instant_event),
+              MatchesRegex(expected_str));
 }
 
 TEST(TraceEvent, CompleteEventToString) {
@@ -208,8 +210,9 @@ TEST(TraceEvent, CompleteEventToString) {
                                            123, 321);
 
   std::string_view expected_str =
-      R"({ "name" : "compile_time", "ph" : "X", "cat" : "pipeline", "pid" : 123, "tid" : 321, "ts" : 0.000401, "dur" : 0.001, "args" : { "duration" : 0.001 } },)";
-  EXPECT_EQ(EventToTraceEventString(complete_event), expected_str);
+      R"(\{ "name" : "compile_time", "ph" : "X", "cat" : "pipeline", "pid" : 123, "tid" : 321, "ts" : ([0-9\.]+), "dur" : 0.001, "args" : \{ "duration" : 0.001 \} \},)";
+  EXPECT_THAT(EventToTraceEventString(complete_event),
+              MatchesRegex(expected_str));
 }
 
 #ifndef NDEBUG
@@ -259,8 +262,8 @@ TEST(TraceEventLogger, MethodCheck) {
   // Checks double `EndLog` calls.
   logger.EndLog();
   std::string_view expected_str =
-      R"({ "name" : "compile_time_init", "ph" : "i", "cat" : "compile_time", "pid" : 123, "tid" : 321, "ts" : 0.001401, "s" : "g", "args" : { "scope" : "g" } },)";
-  EXPECT_THAT(out.GetLog(), ElementsAre("[", expected_str));
+      R"(\{ "name" : "compile_time_init", "ph" : "i", "cat" : "compile_time", "pid" : 123, "tid" : 321, "ts" : ([0-9\.]+), "s" : "g", "args" : \{ "scope" : "g" \} \},)";
+  EXPECT_THAT(out.GetLog(), ElementsAre("[", MatchesRegex(expected_str)));
 }
 
 TEST(TraceEventLogger, LogDifferentTypes) {
@@ -283,12 +286,12 @@ TEST(TraceEventLogger, LogDifferentTypes) {
   logger.EndLog();
 
   std::string_view instant_expected_str =
-      R"({ "name" : "compile_time_init", "ph" : "i", "cat" : "compile_time", "pid" : 123, "tid" : 321, "ts" : 0.001401, "s" : "g", "args" : { "scope" : "g" } },)";
+      R"(\{ "name" : "compile_time_init", "ph" : "i", "cat" : "compile_time", "pid" : 123, "tid" : 321, "ts" : ([0-9\.]+), "s" : "g", "args" : \{ "scope" : "g" \} \},)";
 
   std::string_view complete_expected_str =
-      R"({ "name" : "compile_time", "ph" : "X", "cat" : "pipeline", "pid" : 321, "tid" : 123, "ts" : 0.000401, "dur" : 0.001, "args" : { "duration" : 0.001 } },)";
-  EXPECT_THAT(out.GetLog(),
-              ElementsAre("[", instant_expected_str, complete_expected_str));
+      R"(\{ "name" : "compile_time", "ph" : "X", "cat" : "pipeline", "pid" : 321, "tid" : 123, "ts" : ([0-9\.]+), "dur" : 0.001, "args" : \{ "duration" : 0.001 \} \},)";
+  EXPECT_THAT(out.GetLog(), ElementsAre("[", MatchesRegex(instant_expected_str),
+                                        MatchesRegex(complete_expected_str)));
 }
 
 }  // namespace