diff options
author | Henning Baldersheim <balder@yahoo-inc.com> | 2023-03-01 12:47:50 +0000 |
---|---|---|
committer | Henning Baldersheim <balder@yahoo-inc.com> | 2023-03-01 13:32:40 +0000 |
commit | f66e4be5877a7e5556511ccfe9ecc5ecab4d5366 (patch) | |
tree | f5f634b8e59aa251d0f8b3dcdecfd426a3e5db50 /vespalog | |
parent | 0c766a6506aa82299c2cd1d166fcc3522a962f2f (diff) |
Use typesafe time in vespalog
Diffstat (limited to 'vespalog')
-rw-r--r-- | vespalog/src/test/bufferedlogskiptest.cpp | 17 | ||||
-rw-r--r-- | vespalog/src/test/bufferedlogtest.cpp | 30 | ||||
-rw-r--r-- | vespalog/src/vespa/log/bufferedlogger.cpp | 38 | ||||
-rw-r--r-- | vespalog/src/vespa/log/bufferedlogger.h | 4 | ||||
-rw-r--r-- | vespalog/src/vespa/log/log.cpp | 33 | ||||
-rw-r--r-- | vespalog/src/vespa/log/log.h | 28 |
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); |