diff --git a/src/logging_unittest.cc b/src/logging_unittest.cc index 2b50a257d..efcb0bbaa 100644 --- a/src/logging_unittest.cc +++ b/src/logging_unittest.cc @@ -115,6 +115,7 @@ static void TestWrapper(); static void TestErrno(); static void TestTruncate(); static void TestCustomLoggerDeletionOnShutdown(); +static void TestLogPeriodically(); static int x = -1; static void BM_Check1(int n) { @@ -248,6 +249,7 @@ int main(int argc, char **argv) { TestErrno(); TestTruncate(); TestCustomLoggerDeletionOnShutdown(); + TestLogPeriodically(); fprintf(stdout, "PASS\n"); return 0; @@ -995,6 +997,76 @@ static void TestCustomLoggerDeletionOnShutdown() { EXPECT_FALSE(IsGoogleLoggingInitialized()); } +struct LogStreamTimer { + // Log a "message" every 10ms, 10 times. These numbers are nice compromise between + // total running time of 100ms and the period of 10ms. The period is large enough + // such that any CPU and OS scheduling variation shouldn't affect the results from + // the ideal case by more than 1% (100us or 0.1ms) + static GLOG_CONSTEXPR double LOG_PERIOD_SEC = 0.01; + + // Set an upper limit for the number of times the stream operator can be called. + // Make sure not to exceed this number of times the stream operator is called, + // since it is also the array size and will be indexed by the stream operator. + static GLOG_CONSTEXPR size_t MAX_CALLS = 10; + + static GLOG_CONSTEXPR int64_t LOG_PERIOD_US = 10000; + static GLOG_CONSTEXPR int64_t LOG_PERIOD_TOL_US = 100; + + size_t m_streamTimes = 0; +}; + +#if __cplusplus >= 201103L +struct LogStreamTimerImpl : LogStreamTimer { + std::chrono::steady_clock::time_point m_callTimes[MAX_CALLS]; +}; +// The stream operator is called by LOG_EVERY_T every time a logging event occurs. +// Make sure to save the times for each call as they will be used later to verify +// the time delta between each call. +std::ostream& operator<<(std::ostream& stream, LogStreamTimerImpl& t) { + t.m_callTimes[t.m_streamTimes++] = std::chrono::steady_clock::now(); + return stream; +} +// get elapsed time in microseconds +int64_t elapsedTime_us(const std::chrono::steady_clock::time_point& begin, + const std::chrono::steady_clock::time_point& end) { + return std::chrono::duration_cast((end - begin)).count(); +} +#else +struct LogStreamTimerImpl : LogStreamTimer { + timespec m_callTimes[MAX_CALLS]; +}; +std::ostream& operator<<(std::ostream& stream, LogStreamTimerImpl& t) { + clock_gettime(CLOCK_MONOTONIC, &t.m_callTimes[t.m_streamTimes++]); + return stream; +} +// get elapsed time in microseconds +int64_t elapsedTime_us(const timespec& begin, const timespec& end) { + const int64_t elapsed_ns = ((end.tv_sec - begin.tv_sec) * 1000000000) + (end.tv_nsec - begin.tv_nsec); + return elapsed_ns / 1000; +} +#endif + +static void TestLogPeriodically() { + fprintf(stderr, "==== Test log periodically\n"); + + LogStreamTimerImpl logger; + + while (logger.m_streamTimes < logger.MAX_CALLS) { + LOG_EVERY_T(INFO, LogStreamTimer::LOG_PERIOD_SEC) << logger << "Timed Message #" << logger.m_streamTimes; + } + + // Calculate time between each call in microseconds for higher resolution to minimize + // error. + int64_t usBetweenCalls[logger.MAX_CALLS - 1]; + for (size_t i = 1; i < logger.MAX_CALLS; ++i) { + usBetweenCalls[i - 1] = elapsedTime_us(logger.m_callTimes[i - 1], logger.m_callTimes[i]); + } + + for (auto time : usBetweenCalls) { + EXPECT_NEAR(time, LogStreamTimer::LOG_PERIOD_US, LogStreamTimer::LOG_PERIOD_TOL_US); + } +} + _START_GOOGLE_NAMESPACE_ namespace glog_internal_namespace_ { extern // in logging.cc