log: Mark timestamps for coarseness and print appropriately

Have each timestamp know whether it's coarse or fine. Print six figures
for fine stamps and three for coarse.

Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

3 files changed, 122 insertions, 103 deletions

diff --git a/src/common/ceph_time.cc b/src/common/ceph_time.cc
index f5072b7923d..a5c630a1786 100644
--- a/src/common/ceph_time.cc
+++ b/src/common/ceph_time.cc
@@ -84,25 +84,6 @@ namespace ceph {
 
   }
 
-  namespace logging {
-    void log_clock::to_ceph_timespec(const time_point& t,
-				     struct ceph_timespec& ts) {
-      ts.tv_sec = to_time_t(t);
-      ts.tv_nsec = (t.time_since_epoch() %std::chrono::seconds(1)).count();
-    }
-    struct ceph_timespec log_clock::to_ceph_timespec(
-      const time_point& t) {
-      struct ceph_timespec ts;
-      to_ceph_timespec(t, ts);
-      return ts;
-    }
-    log_clock::time_point log_clock::from_ceph_timespec(
-      const struct ceph_timespec& ts) {
-      return time_point(std::chrono::seconds(ts.tv_sec) +
-			std::chrono::nanoseconds(ts.tv_nsec));
-    }
-  }
-
   using std::chrono::duration_cast;
   using std::chrono::seconds;
   using std::chrono::microseconds;
@@ -153,6 +134,4 @@ namespace ceph {
   operator<< <coarse_mono_clock>(std::ostream& m, const coarse_mono_time& t);
   template std::ostream&
   operator<< <coarse_real_clock>(std::ostream& m, const coarse_real_time& t);
-  template std::ostream&
-  operator<< <logging::log_clock>(std::ostream& m, const logging::log_time& t);
 }
diff --git a/src/log/LogClock.h b/src/log/LogClock.h
index e790dbd2c8f..76156b093b4 100644
--- a/src/log/LogClock.h
+++ b/src/log/LogClock.h
@@ -14,117 +14,134 @@
 
 namespace ceph {
 namespace logging {
+namespace _logclock {
+// Because the underlying representations of a duration can be any
+// arithmetic type we wish, slipping a coarseness tag there is the
+// least hacky way to tag them. I'd also considered doing bit-stealing
+// and just setting the low bit of the representation unconditionally
+// to mark it as fine, BUT that would cut our nanosecond precision in
+// half which sort of obviates the point of 'fine'…admittedly real
+// computers probably don't care. More to the point it wouldn't be
+// durable under arithmetic unless we wrote a whole class to support
+// it /anyway/, and if I'm going to do that I may as well add a bool.
+
+// (Yes I know we don't do arithmetic on log timestamps, but I don't
+// want everything to suddenly break because someone did something
+// that the std::chrono::timepoint contract actually supports.)
+struct taggedrep {
+  uint64_t count;
+  bool coarse;
+
+  explicit taggedrep(uint64_t count) : count(count), coarse(true) {}
+  taggedrep(uint64_t count, bool coarse) : count(count), coarse(coarse) {}
+
+  explicit operator uint64_t() {
+    return count;
+  }
+};
+
+// Proper significant figure support would be a bit excessive. Also
+// we'd have to know the precision of the clocks on Linux and FreeBSD
+// and whatever else we want to support.
+inline taggedrep operator +(const taggedrep& l, const taggedrep& r) {
+  return { l.count + r.count, l.coarse || r.coarse };
+}
+inline taggedrep operator -(const taggedrep& l, const taggedrep& r) {
+  return { l.count - r.count, l.coarse || r.coarse };
+}
+inline taggedrep operator *(const taggedrep& l, const taggedrep& r) {
+  return { l.count * r.count, l.coarse || r.coarse };
+}
+inline taggedrep operator /(const taggedrep& l, const taggedrep& r) {
+  return { l.count / r.count, l.coarse || r.coarse };
+}
+inline taggedrep operator %(const taggedrep& l, const taggedrep& r) {
+  return { l.count % r.count, l.coarse || r.coarse };
+}
+
+// You can compare coarse and fine time. You shouldn't do so in any
+// case where ordering actually MATTERS but in practice people won't
+// actually ping-pong their logs back and forth between them.
+inline bool operator ==(const taggedrep& l, const taggedrep& r) {
+  return l.count == r.count;
+}
+inline bool operator !=(const taggedrep& l, const taggedrep& r) {
+  return l.count != r.count;
+}
+inline bool operator <(const taggedrep& l, const taggedrep& r) {
+  return l.count < r.count;
+}
+inline bool operator <=(const taggedrep& l, const taggedrep& r) {
+  return l.count <= r.count;
+}
+inline bool operator >=(const taggedrep& l, const taggedrep& r) {
+  return l.count >= r.count;
+}
+inline bool operator >(const taggedrep& l, const taggedrep& r) {
+  return l.count > r.count;
+}
+}
 class log_clock {
 public:
-  using duration = timespan;
-  using rep = duration::rep;
-  using period = duration::period;
+  using rep = _logclock::taggedrep;
+  using period = std::nano;
+  using duration = std::chrono::duration<rep, period>;
   // The second template parameter defaults to the clock's duration
   // type.
   using time_point = std::chrono::time_point<log_clock>;
   static constexpr const bool is_steady = false;
 
-  void coarsen() {
-    appropriate_now = coarse_now;
-  }
-
-  void refine() {
-    appropriate_now = fine_now;
-  }
-
   time_point now() noexcept {
     return appropriate_now();
   }
 
-  static bool is_zero(const time_point& t) {
-    return (t == time_point::min());
-  }
-
-  // Allow conversion to/from any clock with the same interface as
-  // std::chrono::system_clock)
-  template<typename Clock, typename Duration>
-  static time_point to_system_time_point(
-    const std::chrono::time_point<Clock, Duration>& t) {
-    return time_point(seconds(Clock::to_time_t(t)) +
-		      std::chrono::duration_cast<duration>(
-			t.time_since_epoch() % std::chrono::seconds(1)));
-  }
-  template<typename Clock, typename Duration>
-  static std::chrono::time_point<Clock, Duration> to_system_time_point(
-    const time_point& t) {
-    return (Clock::from_time_t(to_time_t(t)) +
-	    std::chrono::duration_cast<Duration>(t.time_since_epoch() %
-						 std::chrono::seconds(1)));
-  }
-
-  static time_t to_time_t(const time_point& t) noexcept {
-    return std::chrono::duration_cast<std::chrono::seconds>(
-      t.time_since_epoch()).count();
-  }
-  static time_point from_time_t(const time_t& t) noexcept {
-    return time_point(std::chrono::seconds(t));
-  }
-
-  static void to_timespec(const time_point& t, struct timespec& ts) {
-    ts.tv_sec = to_time_t(t);
-    ts.tv_nsec = (t.time_since_epoch() % std::chrono::seconds(1)).count();
-  }
-  static struct timespec to_timespec(const time_point& t) {
-    struct timespec ts;
-    to_timespec(t, ts);
-    return ts;
-  }
-  static time_point from_timespec(const struct timespec& ts) {
-    return time_point(std::chrono::seconds(ts.tv_sec) +
-		      std::chrono::nanoseconds(ts.tv_nsec));
+  void coarsen() {
+    appropriate_now = coarse_now;
   }
 
-  static void to_ceph_timespec(const time_point& t,
-			       struct ceph_timespec& ts);
-  static struct ceph_timespec to_ceph_timespec(const time_point& t);
-  static time_point from_ceph_timespec(const struct ceph_timespec& ts);
-
-  static void to_timeval(const time_point& t, struct timeval& tv) {
-    tv.tv_sec = to_time_t(t);
-    tv.tv_usec = std::chrono::duration_cast<std::chrono::microseconds>(
-      t.time_since_epoch() % std::chrono::seconds(1)).count();
-  }
-  static struct timeval to_timeval(const time_point& t) {
-    struct timeval tv;
-    to_timeval(t, tv);
-    return tv;
-  }
-  static time_point from_timeval(const struct timeval& tv) {
-    return time_point(std::chrono::seconds(tv.tv_sec) +
-		      std::chrono::microseconds(tv.tv_usec));
+  void refine() {
+    appropriate_now = fine_now;
   }
 
-  static double to_double(const time_point& t) {
-    return std::chrono::duration<double>(t.time_since_epoch()).count();
-  }
-  static time_point from_double(const double d) {
-    return time_point(std::chrono::duration_cast<duration>(
-			std::chrono::duration<double>(d)));
+  // Since our formatting is done in microseconds and we're using it
+  // anyway, we may as well keep this one
+  static timeval to_timeval(time_point t) {
+    auto rep = t.time_since_epoch().count();
+    timespan ts(rep.count);
+    return { std::chrono::duration_cast<std::chrono::seconds>(ts).count(),
+	     std::chrono::duration_cast<std::chrono::microseconds>(
+	       ts % std::chrono::seconds(1)).count() };
   }
 private:
   static time_point coarse_now() {
-    return time_point(coarse_real_clock::now().time_since_epoch());
+    return time_point(
+      duration(_logclock::taggedrep(coarse_real_clock::now()
+				    .time_since_epoch().count(), true)));
   }
   static time_point fine_now() {
-    return time_point(real_clock::now().time_since_epoch());
+    return time_point(
+      duration(_logclock::taggedrep(real_clock::now()
+				    .time_since_epoch().count(), false)));
   }
   time_point(*appropriate_now)() = coarse_now;
 };
 using log_time = log_clock::time_point;
 inline int append_time(const log_time& t, char *out, int outlen) {
+  bool coarse = t.time_since_epoch().count().coarse;
   auto tv = log_clock::to_timeval(t);
   std::tm bdt;
   localtime_r(&tv.tv_sec, &bdt);
 
-  auto r = std::snprintf(out, outlen,
-			 "%04d-%02d-%02d %02d:%02d:%02d.%06ld",
-			 bdt.tm_year + 1900, bdt.tm_mon + 1, bdt.tm_mday,
-			 bdt.tm_hour, bdt.tm_min, bdt.tm_sec, tv.tv_usec);
+  int r;
+  if (coarse) {
+    r = std::snprintf(out, outlen, "%04d-%02d-%02d %02d:%02d:%02d.%03ld",
+		      bdt.tm_year + 1900, bdt.tm_mon + 1, bdt.tm_mday,
+		      bdt.tm_hour, bdt.tm_min, bdt.tm_sec, tv.tv_usec / 1000);
+  } else {
+    r = std::snprintf(out, outlen, "%04d-%02d-%02d %02d:%02d:%02d.%06ld",
+		      bdt.tm_year + 1900, bdt.tm_mon + 1, bdt.tm_mday,
+		      bdt.tm_hour, bdt.tm_min, bdt.tm_sec, tv.tv_usec);
+  }
   // Since our caller just adds the return value to something without
   // checking it…
   ceph_assert(r >= 0);
diff --git a/src/log/test.cc b/src/log/test.cc
index 6ec9e751b7e..2ae63a741c8 100644
--- a/src/log/test.cc
+++ b/src/log/test.cc
@@ -251,3 +251,26 @@ TEST(Log, TimeSwitch)
   log.flush();
   log.stop();
 }
+
+TEST(Log, TimeFormat)
+{
+  static constexpr auto buflen = 128u;
+  char buf[buflen];
+  ceph::logging::log_clock clock;
+  {
+    clock.coarsen();
+    auto t = clock.now();
+    ceph::logging::append_time(t, buf, buflen);
+    auto c = std::strrchr(buf, '.');
+    ASSERT_NE(c, nullptr);
+    ASSERT_EQ(strlen(c + 1), 3);
+  }
+  {
+    clock.refine();
+    auto t = clock.now();
+    ceph::logging::append_time(t, buf, buflen);
+    auto c = std::strrchr(buf, '.');
+    ASSERT_NE(c, nullptr);
+    ASSERT_EQ(std::strlen(c + 1), 6);
+  }
+}