testing period logging

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<std::chrono::microseconds>((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