Use typesafe time in vespalog

6 files changed, 87 insertions, 63 deletions

diff --git a/vespalog/src/test/bufferedlogskiptest.cpp b/vespalog/src/test/bufferedlogskiptest.cpp
index 8b7f1982678..abb5705b612 100644
--- a/vespalog/src/test/bufferedlogskiptest.cpp
+++ b/vespalog/src/test/bufferedlogskiptest.cpp
@@ -9,6 +9,15 @@
 
 LOG_SETUP("bufferedlogskiptest");
 
+using namespace std::literals::chrono_literals;
+
+/** Test timer returning just a given time. Used in tests to fake time. */
+struct TestTimer : public ns_log::Timer {
+    uint64_t & _time;
+    TestTimer(uint64_t & timeVar) : _time(timeVar) { }
+    ns_log::system_time getTimestamp() const override { return ns_log::system_time(std::chrono::microseconds(_time)); }
+};
+
 std::string readFile(const std::string& file) {
     std::ostringstream ost;
     std::ifstream is(file.c_str());
@@ -62,8 +71,8 @@ void testSkipBufferOnDebug(const std::string& file, uint64_t & timer)
 void reset(uint64_t & timer) {
     timer = 0;
     ns_log::BufferedLogger::instance().setMaxCacheSize(10);
-    ns_log::BufferedLogger::instance().setMaxEntryAge(300);
-    ns_log::BufferedLogger::instance().setCountFactor(5);
+    ns_log::BufferedLogger::instance().setMaxEntryAge(300s);
+    ns_log::BufferedLogger::instance().setCountFactor(5s);
 }
 
 int
@@ -75,8 +84,8 @@ main(int argc, char **argv)
     }
     ns_log::Logger::fakePid = true;
     uint64_t timer;
-    ns_log_logger.setTimer(std::unique_ptr<ns_log::Timer>(new ns_log::TestTimer(timer)));
-    ns_log::BufferedLogger::instance().setTimer(std::unique_ptr<ns_log::Timer>(new ns_log::TestTimer(timer)));
+    ns_log_logger.setTimer(std::make_unique<TestTimer>(timer));
+    ns_log::BufferedLogger::instance().setTimer(std::make_unique<TestTimer>(timer));
 
     reset(timer);
     testSkipBufferOnDebug(argv[1], timer);
diff --git a/vespalog/src/test/bufferedlogtest.cpp b/vespalog/src/test/bufferedlogtest.cpp
index 365f8fb85a7..d3fc1c28d63 100644
--- a/vespalog/src/test/bufferedlogtest.cpp
+++ b/vespalog/src/test/bufferedlogtest.cpp
@@ -12,6 +12,16 @@
 
 LOG_SETUP("bufferedlogtest");
 
+using namespace std::literals::chrono_literals;
+
+
+/** Test timer returning just a given time. Used in tests to fake time. */
+struct TestTimer : public ns_log::Timer {
+    uint64_t & _time;
+    TestTimer(uint64_t & timeVar) : _time(timeVar) { }
+    ns_log::system_time getTimestamp() const override { return ns_log::system_time(std::chrono::microseconds(_time)); }
+};
+
 std::string readFile(const std::string& file) {
     std::ostringstream ost;
     std::ifstream is(file.c_str());
@@ -112,9 +122,9 @@ void testThatEntriesWithHighCountsAreEventuallyRemoved(
         // Should eventually throw out the entries with high count
     timer = 10 * 1000000 + 4;
         // Make sure we don't remove due to age.
-    ns_log::BufferedLogger::instance().setMaxEntryAge(1000000);
+    ns_log::BufferedLogger::instance().setMaxEntryAge(1000000s);
         // Let each count, count for 5 seconds.
-    ns_log::BufferedLogger::instance().setCountFactor(5);
+    ns_log::BufferedLogger::instance().setCountFactor(5s);
 
     LOGBM(info, "Starting up, using logfile %s", file.c_str());
     timer = 100 * 1000000 + 4;
@@ -147,9 +157,9 @@ void testThatEntriesExpire(
         // Test that we don't keep entries longer than max age
     timer = 10 * 1000000 + 4;
         // Time out after 120 seconds
-    ns_log::BufferedLogger::instance().setMaxEntryAge(120);
+    ns_log::BufferedLogger::instance().setMaxEntryAge(120s);
         // Let counts count much, so they expire due to time instead
-    ns_log::BufferedLogger::instance().setCountFactor(100000);
+    ns_log::BufferedLogger::instance().setCountFactor(100000s);
 
     LOGBM(info, "Starting up, using logfile %s", file.c_str());
     timer = 100 * 1000000 + 4;
@@ -217,9 +227,9 @@ void testThatHighCountEntriesDontStarveOthers(
     std::cerr << "testThatHighCountEntriesDontStarveOthers ...\n";
     timer = 10 * 1000000 + 4;
         // Long time out, we don't want to rely on timeout to prevent starvation
-    ns_log::BufferedLogger::instance().setMaxEntryAge(12000000);
+    ns_log::BufferedLogger::instance().setMaxEntryAge(12000000s);
         // Let counts count much, so they score high
-    ns_log::BufferedLogger::instance().setCountFactor(100000);
+    ns_log::BufferedLogger::instance().setCountFactor(100000s);
 
     LOGBM(info, "Starting up, using logfile %s", file.c_str());
     timer = 100 * 1000000;
@@ -372,8 +382,8 @@ void testNonBufferedLoggerTriggersBufferedLogTrim(const std::string& file,
 
 void reset(uint64_t& timer) {
     timer = 0;
-    ns_log::BufferedLogger::instance().setMaxEntryAge(300);
-    ns_log::BufferedLogger::instance().setCountFactor(5);
+    ns_log::BufferedLogger::instance().setMaxEntryAge(300s);
+    ns_log::BufferedLogger::instance().setCountFactor(5s);
 }
 
 int
@@ -386,8 +396,8 @@ main(int argc, char **argv)
     ns_log::Logger::fakePid = true;
     ns_log::BufferedLogger::instance().setMaxCacheSize(10);
     uint64_t timer;
-    ns_log_logger.setTimer(std::unique_ptr<ns_log::Timer>(new ns_log::TestTimer(timer)));
-    ns_log::BufferedLogger::instance().setTimer(std::unique_ptr<ns_log::Timer>(new ns_log::TestTimer(timer)));
+    ns_log_logger.setTimer(std::make_unique<TestTimer>(timer));
+    ns_log::BufferedLogger::instance().setTimer(std::make_unique<TestTimer>(timer));
 
     reset(timer);
     testThatEntriesWithHighCountIsKept(argv[1], timer);
diff --git a/vespalog/src/vespa/log/bufferedlogger.cpp b/vespalog/src/vespa/log/bufferedlogger.cpp
index 33ff3da7366..7ad878a568c 100644
--- a/vespalog/src/vespa/log/bufferedlogger.cpp
+++ b/vespalog/src/vespa/log/bufferedlogger.cpp
@@ -14,6 +14,8 @@
 #include <cstdarg>
 #include <mutex>
 
+using namespace std::literals::chrono_literals;
+
 namespace ns_log {
 
 // implementation details for BufferedLogger
@@ -25,7 +27,7 @@ public:
     /** Lock needed to access cache. */
     mutable std::mutex _mutex;
 
-    static uint64_t _countFactor;
+    static duration _countFactor;
 
     /** Struct keeping information about log message. */
     struct Entry {
@@ -35,7 +37,7 @@ public:
         std::string _token;
         std::string _message;
         uint32_t _count;
-        uint64_t _timestamp;
+        system_time _timestamp;
         Logger* _logger;
 
         Entry(const Entry &);
@@ -44,13 +46,13 @@ public:
         Entry & operator=(Entry &&) noexcept;
         Entry(Logger::LogLevel level, const char* file, int line,
               const std::string& token, const std::string& message,
-              uint64_t timestamp, Logger&);
+              system_time timestamp, Logger&);
         ~Entry();
 
         bool operator==(const Entry& entry) const;
         bool operator<(const Entry& entry) const;
 
-        uint64_t getAgeFactor() const;
+        system_time getAgeFactor() const;
 
         std::string toString() const;
     };
@@ -73,7 +75,7 @@ public:
             >,
             boost::multi_index::ordered_non_unique<
                 boost::multi_index::const_mem_fun<
-                    Entry, uint64_t, &Entry::getAgeFactor
+                    Entry, system_time, &Entry::getAgeFactor
                 >
             >
         >
@@ -85,7 +87,7 @@ public:
     LogCacheBack _cacheBack;
 
     uint32_t _maxCacheSize;
-    uint64_t _maxEntryAge;
+    duration _maxEntryAge;
 
     /** Empty buffer and write all log entries in it. */
     void flush();
@@ -97,7 +99,7 @@ public:
      * Flush parts of cache, so we're below max size and only have messages of
      * acceptable age. Calling this, _mutex should already be locked.
      */
-    void trimCache(uint64_t currentTime);
+    void trimCache(system_time currentTime);
 
     /**
      * Trim the cache up to current time. Used externally to check if we
@@ -125,11 +127,11 @@ public:
 };
 
 // Let each hit count for 5 seconds
-uint64_t BackingBuffer::_countFactor = VESPA_LOG_COUNTAGEFACTOR * 1000 * 1000;
+duration BackingBuffer::_countFactor = VESPA_LOG_COUNTAGEFACTOR * 1s;
 
 BackingBuffer::Entry::Entry(Logger::LogLevel level, const char* file, int line,
                              const std::string& token, const std::string& msg,
-                             uint64_t timestamp, Logger& l)
+                             system_time timestamp, Logger& l)
     : _level(level),
       _file(file),
       _line(line),
@@ -171,11 +173,11 @@ BackingBuffer::Entry::toString() const
     std::ostringstream ost;
     ost << "Entry(" << _level << ", " << _file << ":" << _line << ": "
         << _message << " [" << _token << "], count " << _count
-        << ", timestamp " << _timestamp << ")";
+        << ", timestamp " << count_us(_timestamp.time_since_epoch()) << ")";
     return ost.str();
 }
 
-uint64_t
+system_time
 BackingBuffer::Entry::getAgeFactor() const
 {
     return _timestamp + _countFactor * _count;
@@ -288,7 +290,7 @@ BufferedLogger::flush() {
 }
 
 void
-BackingBuffer::trimCache(uint64_t currentTime)
+BackingBuffer::trimCache(system_time currentTime)
 {
         // Remove entries that have been in here too long.
     while (!_cacheBack.empty() &&
@@ -330,8 +332,8 @@ BackingBuffer::log(const Entry& e) const
     if (e._count > 1) {
         std::ostringstream ost;
         ost << e._message << " (Repeated " << (e._count - 1)
-            << " times since " << (e._timestamp / 1000000) << "."
-            << std::setw(6) << std::setfill('0') << (e._timestamp % 1000000)
+            << " times since " << count_s(e._timestamp.time_since_epoch()) << "."
+            << std::setw(6) << std::setfill('0') << (count_us(e._timestamp.time_since_epoch()) % 1000000)
             << ")";
         e._logger->doLogCore(_timer->getTimestamp(), e._level, e._file.c_str(),
                              e._line, ost.str().c_str(), ost.str().size());
@@ -365,13 +367,13 @@ BufferedLogger::setMaxCacheSize(uint32_t size) {
 }
 
 void
-BufferedLogger::setMaxEntryAge(uint64_t seconds) {
-    _backing->_maxEntryAge = seconds * 1000000;
+BufferedLogger::setMaxEntryAge(duration maxAge) {
+    _backing->_maxEntryAge = maxAge;
 }
 
 void
-BufferedLogger::setCountFactor(uint64_t factor) {
-    _backing->_countFactor = factor * 1000000;
+BufferedLogger::setCountFactor(duration factor) {
+    _backing->_countFactor = factor;
 }
 
 /** Set a fake timer to use for log messages. Used in unit testing. */
diff --git a/vespalog/src/vespa/log/bufferedlogger.h b/vespalog/src/vespa/log/bufferedlogger.h
index 8baa32445a5..31e194e63bb 100644
--- a/vespalog/src/vespa/log/bufferedlogger.h
+++ b/vespalog/src/vespa/log/bufferedlogger.h
@@ -178,8 +178,8 @@ public:
     // to easier be able to test all aspects of the buffer, and be independent
     // of the default settings for applications
     void setMaxCacheSize(uint32_t size);
-    void setMaxEntryAge(uint64_t seconds);
-    void setCountFactor(uint64_t factor);
+    void setMaxEntryAge(duration seconds);
+    void setCountFactor(duration factor);
 
     void doLog(Logger&, Logger::LogLevel level, const char *file, int line,
                const std::string& token,
diff --git a/vespalog/src/vespa/log/log.cpp b/vespalog/src/vespa/log/log.cpp
index 7430815122d..9ca993b84fc 100644
--- a/vespalog/src/vespa/log/log.cpp
+++ b/vespalog/src/vespa/log/log.cpp
@@ -20,13 +20,9 @@ LOG_SETUP_INDIRECT(".log", "$Id$");
 
 namespace ns_log {
 
-uint64_t Timer::getTimestamp() const {
-    struct timeval tv;
-    gettimeofday(&tv, nullptr);
-    uint64_t timestamp = tv.tv_sec;
-    timestamp *= 1000000;
-    timestamp += tv.tv_usec;
-    return timestamp;
+system_time
+Timer::getTimestamp() const {
+    return std::chrono::system_clock::now();
 }
 
 LogTarget *Logger::_target = 0;
@@ -220,8 +216,7 @@ Logger::tryLog(int sizeofPayload, LogLevel level, const char *file, int line, co
     const int actualSize = vsnprintf(payload, sizeofPayload, fmt, args);
 
     if (actualSize < sizeofPayload) {
-        uint64_t timestamp = _timer->getTimestamp();
-        doLogCore(timestamp, level, file, line, payload, actualSize);
+        doLogCore(_timer->getTimestamp(), level, file, line, payload, actualSize);
     }
     delete[] payload;
     return actualSize;
@@ -242,8 +237,9 @@ Logger::doLog(LogLevel level, const char *file, int line, const char *fmt, ...)
     ns_log::BufferedLogger::instance().trimCache();
 }
 
-void Logger::doLogCore(uint64_t timestamp, LogLevel level,
-                       const char *file, int line, const char *msg, size_t msgSize)
+void
+Logger::doLogCore(system_time timestamp, LogLevel level,
+                  const char *file, int line, const char *msg, size_t msgSize)
 {
     const size_t sizeofEscapedPayload(msgSize*4+1);
     const size_t sizeofTotalMessage(sizeofEscapedPayload + 1000);
@@ -281,23 +277,23 @@ void Logger::doLogCore(uint64_t timestamp, LogLevel level,
         // found to be too inaccurate.
     int32_t tid = (fakePid ? -1 : gettid(pthread_self()) % 0xffff);
 
+    time_t secs = count_s(timestamp.time_since_epoch());
+    uint32_t usecs_part = count_us(timestamp.time_since_epoch()) % 1000000;
     if (_target->makeHumanReadable()) {
-        time_t secs = static_cast<time_t>(timestamp / 1000000);
         struct tm tmbuf;
         localtime_r(&secs, &tmbuf);
         char timebuf[100];
         strftime(timebuf, 100, "%Y-%m-%d %H:%M:%S", &tmbuf);
         snprintf(totalMessage.get(), sizeofTotalMessage,
                  "[%s.%06u] %d/%d (%s%s) %s: %s\n",
-                 timebuf, static_cast<unsigned int>(timestamp % 1000000),
+                 timebuf, usecs_part,
                  fakePid ? -1 : getpid(), tid,
                  _prefix, _appendix,
                  levelName(level), msg);
     } else if (level == debug || level == spam) {
         snprintf(totalMessage.get(), sizeofTotalMessage,
-                 "%u.%06u\t%s\t%d/%d\t%s\t%s%s\t%s\t%s:%d %s%s\n",
-                 static_cast<unsigned int>(timestamp / 1000000),
-                 static_cast<unsigned int>(timestamp % 1000000),
+                 "%lu.%06u\t%s\t%d/%d\t%s\t%s%s\t%s\t%s:%d %s%s\n",
+                 secs, usecs_part,
                  _hostname, fakePid ? -1 : getpid(), tid,
                  _serviceName, _prefix,
                  _appendix, levelName(level), file, line,
@@ -305,9 +301,8 @@ void Logger::doLogCore(uint64_t timestamp, LogLevel level,
                  escapedPayload.get());
     } else {
         snprintf(totalMessage.get(), sizeofTotalMessage,
-                 "%u.%06u\t%s\t%d/%d\t%s\t%s%s\t%s\t%s\n",
-                 static_cast<unsigned int>(timestamp / 1000000),
-                 static_cast<unsigned int>(timestamp % 1000000),
+                 "%lu.%06u\t%s\t%d/%d\t%s\t%s%s\t%s\t%s\n",
+                 secs, usecs_part,
                  _hostname, fakePid ? -1 : getpid(), tid,
                  _serviceName, _prefix,
                  _appendix, levelName(level), escapedPayload.get());
diff --git a/vespalog/src/vespa/log/log.h b/vespalog/src/vespa/log/log.h
index 888e24a0f28..88d24ba7e18 100644
--- a/vespalog/src/vespa/log/log.h
+++ b/vespalog/src/vespa/log/log.h
@@ -3,12 +3,15 @@
 
 #include <memory>
 #include <cstdint>
-#include <sys/types.h> // for pid_t
 #include <new>         // for placement new
 #include <cstdlib>     // for malloc
 #include <cstring>     // for memset
 #include <cstdarg>     // for va_list
 #include <cinttypes>
+#include <chrono>
+#include <sys/types.h> // for pid_t
+
+
 
 /**
  * If this macro is defined, the regular LOG calls will go through the
@@ -144,19 +147,24 @@ namespace ns_log {
 
 class LogTarget;
 class ControlFile;
+using system_time  = std::chrono::system_clock::time_point;
+using duration  = std::chrono::nanoseconds;
+
+constexpr int64_t
+count_s(duration d) {
+    return std::chrono::duration_cast<std::chrono::seconds>(d).count();
+}
+
+constexpr int64_t
+count_us(duration d) {
+    return std::chrono::duration_cast<std::chrono::microseconds>(d).count();
+}
 
 // XXX this is way too complicated, must be some simpler way to do this
 /** Timer class used to retrieve timestamp, such that we can override in test */
 struct Timer {
     virtual ~Timer() = default;
-    virtual uint64_t getTimestamp() const;
-};
-
-/** Test timer returning just a given time. Used in tests to fake time. */
-struct TestTimer : public Timer {
-    uint64_t & _time;
-    TestTimer(uint64_t & timeVar) : _time(timeVar) { }
-    uint64_t getTimestamp() const override { return _time; }
+    virtual system_time getTimestamp() const;
 };
 
 class Logger {
@@ -219,7 +227,7 @@ public:
      *
      * @param timestamp Time in microseconds.
      */
-    void doLogCore(uint64_t timestamp, LogLevel level,
+    void doLogCore(system_time timestamp, LogLevel level,
                    const char *file, int line, const char *msg, size_t msgSize);
     void doEventStarting(const char *name);
     void doEventStopping(const char *name, const char *why);