From afaf48a2636a46084279d1c6076aa67c3fe12136 Mon Sep 17 00:00:00 2001 From: "Adam C. Emerson" Date: Fri, 6 Oct 2017 17:15:43 -0400 Subject: [PATCH] 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 --- src/common/ceph_time.cc | 21 ----- src/log/LogClock.h | 181 ++++++++++++++++++++++------------------ src/log/test.cc | 23 +++++ 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<< (std::ostream& m, const coarse_mono_time& t); template std::ostream& operator<< (std::ostream& m, const coarse_real_time& t); - template std::ostream& - operator<< (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,16 +14,87 @@ 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; // The second template parameter defaults to the clock's duration // type. using time_point = std::chrono::time_point; static constexpr const bool is_steady = false; + time_point now() noexcept { + return appropriate_now(); + } + void coarsen() { appropriate_now = coarse_now; } @@ -32,99 +103,45 @@ public: 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 - static time_point to_system_time_point( - const std::chrono::time_point& t) { - return time_point(seconds(Clock::to_time_t(t)) + - std::chrono::duration_cast( - t.time_since_epoch() % std::chrono::seconds(1))); - } - template - static std::chrono::time_point to_system_time_point( - const time_point& t) { - return (Clock::from_time_t(to_time_t(t)) + - std::chrono::duration_cast(t.time_since_epoch() % - std::chrono::seconds(1))); - } - - static time_t to_time_t(const time_point& t) noexcept { - return std::chrono::duration_cast( - 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)); - } - - 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( - 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)); - } - - static double to_double(const time_point& t) { - return std::chrono::duration(t.time_since_epoch()).count(); - } - static time_point from_double(const double d) { - return time_point(std::chrono::duration_cast( - std::chrono::duration(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(ts).count(), + std::chrono::duration_cast( + 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); + } +}