Merge pull request #669 from darbitman/log-every-time-period

log messages periodically (time-based)

AUTHORS

@@ -13,6 +13,7 @@ Abhishek Parmar <abhishek@orng.net>
 Andrew Schwartzmeyer <andrew@schwartzmeyer.com>
 Andy Ying <andy@trailofbits.com>
 Brian Silverman <bsilver16384@gmail.com>
+Dmitriy Arbitman <d.arbitman@gmail.com>
 Google Inc.
 Guillaume Dumont <dumont.guillaume@gmail.com>
 Marco Wang <m.aesophor@gmail.com>

CMakeLists.txt

@@ -242,6 +242,17 @@ std::atomic<int> i;
 int main() { }
 " HAVE_CXX11_ATOMIC)
 
+check_cxx_source_compiles ("
+constexpr int x = 0;
+int main() { }
+" HAVE_CXX11_CONSTEXPR)
+
+check_cxx_source_compiles ("
+#include <chrono>
+std::chrono::seconds s;
+int main() { }
+" HAVE_CXX11_CHRONO)
+
 check_cxx_source_compiles ("
 #include <cstddef>
 void foo(std::nullptr_t) {}
@@ -389,6 +400,18 @@ else (HAVE_USING_OPERATOR)
   set (ac_cv_cxx_using_operator 0)
 endif (HAVE_USING_OPERATOR)
 
+if (HAVE_CXX11_CONSTEXPR)
+  set (ac_cv_cxx11_constexpr 1)
+else (HAVE_CXX11_CONSTEXPR)
+  set (ac_cv_cxx11_constexpr 0)
+endif (HAVE_CXX11_CONSTEXPR)
+
+if (HAVE_CXX11_CHRONO)
+  set (ac_cv_cxx11_chrono 1)
+else (HAVE_CXX11_CHRONO)
+  set (ac_cv_cxx11_chrono 0)
+endif (HAVE_CXX11_CHRONO)
+
 if (HAVE_CXX11_NULLPTR_T)
   set (ac_cv_cxx11_nullptr_t 1)
 else (HAVE_CXX11_NULLPTR_T)

CONTRIBUTORS

@@ -28,6 +28,7 @@ Andrew Schwartzmeyer <andrew@schwartzmeyer.com>
 Andy Ying <andy@trailofbits.com>
 Bret McKee <bretmckee@google.com>
 Brian Silverman <bsilver16384@gmail.com>
+Dmitriy Arbitman <d.arbitman@gmail.com>
 Fumitoshi Ukai <ukai@google.com>
 Guillaume Dumont <dumont.guillaume@gmail.com>
 Håkan L. S. Younes <hyounes@google.com>

README.rst

@@ -346,6 +346,19 @@ output to the first n occurrences:
 Outputs log messages for the first 20 times it is executed. Again, the
 ``google::COUNTER`` identifier indicates which repetition is happening.
 
+Other times, it is desired to only log a message periodically based on a time.
+So for example, to log a message every 10ms:
+
+.. code:: cpp
+
+   LOG_EVERY_T(INFO, 0.01) << "Got a cookie";
+
+Or every 2.35s:
+
+.. code:: cpp
+
+   LOG_EVERY_T(INFO, 2.35) << "Got a cookie";
+
 Debug Mode Support
 ~~~~~~~~~~~~~~~~~~
 

bazel/glog.bzl

@@ -189,6 +189,8 @@ def glog_library(namespace = "google", with_gflags = 1, **kwargs):
 
     common_config = {
         "@ac_cv_cxx11_atomic@": "1",
+        "@ac_cv_cxx11_constexpr@": "1",
+        "@ac_cv_cxx11_chrono@": "1",
         "@ac_cv_cxx11_nullptr_t@": "1",
         "@ac_cv_cxx_using_operator@": "1",
         "@ac_cv_have_inttypes_h@": "0",

src/config.h.cmake.in

@@ -195,6 +195,9 @@
 /* Check whether C++11 atomic is available */
 #cmakedefine HAVE_CXX11_ATOMIC ${HAVE_CXX11_ATOMIC}
 
+/* Check whether C++11 chrono is available */
+#cmakedefine HAVE_CXX11_CHRONO ${HAVE_CXX11_CHRONO}
+
 /* Check whether C++11 nullptr_t is available */
 #cmakedefine HAVE_CXX11_NULLPTR_T ${HAVE_CXX11_NULLPTR_T}
 

src/glog/logging.h.in

@@ -36,6 +36,10 @@
 #ifndef _LOGGING_H_
 #define _LOGGING_H_
 
+#if @ac_cv_cxx11_chrono@
+#include <chrono>
+#endif
+
 #include <cerrno>
 #include <cstddef>
 #include <cstring>
@@ -984,6 +988,17 @@ PLOG_IF(FATAL, GOOGLE_PREDICT_BRANCH_NOT_TAKEN((invocation) == -1))    \
 #define LOG_OCCURRENCES LOG_EVERY_N_VARNAME(occurrences_, __LINE__)
 #define LOG_OCCURRENCES_MOD_N LOG_EVERY_N_VARNAME(occurrences_mod_n_, __LINE__)
 
+#if @ac_cv_cxx11_constexpr@
+#define GLOG_CONSTEXPR constexpr
+#else
+#define GLOG_CONSTEXPR const
+#endif
+
+#define LOG_TIME_PERIOD LOG_EVERY_N_VARNAME(timePeriod_, __LINE__)
+#define LOG_PREVIOUS_TIME_RAW LOG_EVERY_N_VARNAME(previousTimeRaw_, __LINE__)
+#define LOG_TIME_DELTA LOG_EVERY_N_VARNAME(deltaTime_, __LINE__)
+#define LOG_CURRENT_TIME LOG_EVERY_N_VARNAME(currentTime_, __LINE__)
+#define LOG_PREVIOUS_TIME LOG_EVERY_N_VARNAME(previousTime_, __LINE__)
 
 #if defined(__has_feature)
 #define _GLOG_HAS_FEATURE(...) __has_feature(__VA_ARGS__)
@@ -1016,6 +1031,51 @@ extern "C" void AnnotateBenignRaceSized(
 namespace google {
 #endif
 
+#if @ac_cv_cxx11_chrono@ && @ac_cv_cxx11_atomic@ // Have <chrono> and <atomic>
+#define SOME_KIND_OF_LOG_EVERY_T(severity, seconds) \
+  GLOG_CONSTEXPR std::chrono::duration<double, std::ratio<1, 1>> LOG_TIME_PERIOD(seconds); \
+  static std::atomic<int64> LOG_PREVIOUS_TIME_RAW; \
+  _GLOG_IFDEF_THREAD_SANITIZER( \
+          AnnotateBenignRaceSized(__FILE__, __LINE__, &LOG_TIME_PERIOD, sizeof(int64), "")); \
+  _GLOG_IFDEF_THREAD_SANITIZER( \
+          AnnotateBenignRaceSized(__FILE__, __LINE__, &LOG_PREVIOUS_TIME_RAW, sizeof(int64), "")); \
+  const auto LOG_CURRENT_TIME = std::chrono::steady_clock::now().time_since_epoch(); \
+  const decltype(LOG_CURRENT_TIME) LOG_PREVIOUS_TIME(LOG_PREVIOUS_TIME_RAW.load(std::memory_order_relaxed)); \
+  const auto LOG_TIME_DELTA = LOG_CURRENT_TIME - LOG_PREVIOUS_TIME; \
+  if (LOG_TIME_DELTA > LOG_TIME_PERIOD) \
+    LOG_PREVIOUS_TIME_RAW.store(LOG_CURRENT_TIME.count(), std::memory_order_relaxed); \
+  if (LOG_TIME_DELTA > LOG_TIME_PERIOD) @ac_google_namespace@::LogMessage( \
+        __FILE__, __LINE__, @ac_google_namespace@::GLOG_ ## severity).stream()
+#elif defined(OS_WINDOWS)
+#define SOME_KIND_OF_LOG_EVERY_T(severity, seconds) \
+  GLOG_CONSTEXPR int64 LOG_TIME_PERIOD(seconds * 1000000000.0); \
+  static int64 LOG_PREVIOUS_TIME = 0; \
+  int64 LOG_TIME_DELTA = 0; \
+  { \
+    LARGE_INTEGER currTime; \
+    LARGE_INTEGER freq; \
+    QueryPerformanceCounter(&currTime); \
+    QueryPerformanceFrequency(&freq); \
+    LOG_TIME_DELTA = (currTime.QuadPart * 1000000000.0 / freq.QuadPart) - LOG_PREVIOUS_TIME; \
+  } \
+  if (LOG_TIME_DELTA > LOG_TIME_PERIOD) InterlockedExchangeAdd64(&LOG_PREVIOUS_TIME, LOG_TIME_DELTA); \
+  if (LOG_TIME_DELTA > LOG_TIME_PERIOD) google::LogMessage( \
+        __FILE__, __LINE__, google::GLOG_ ## severity).stream()
+#else
+#define SOME_KIND_OF_LOG_EVERY_T(severity, seconds) \
+  GLOG_CONSTEXPR int64 LOG_TIME_PERIOD(seconds * 1000000000.0); \
+  static int64 LOG_PREVIOUS_TIME; \
+  int64 LOG_TIME_DELTA = 0; \
+  { \
+    timespec currentTime{}; \
+    clock_gettime(CLOCK_MONOTONIC, &currentTime); \
+    LOG_TIME_DELTA = (currentTime.tv_sec * 1000000000 + currentTime.tv_nsec) - LOG_PREVIOUS_TIME; \
+  } \
+  if (LOG_TIME_DELTA > LOG_TIME_PERIOD) __sync_add_and_fetch(&LOG_PREVIOUS_TIME, LOG_TIME_DELTA); \
+  if (LOG_TIME_DELTA > LOG_TIME_PERIOD) @ac_google_namespace@::LogMessage( \
+        __FILE__, __LINE__, @ac_google_namespace@::GLOG_ ## severity).stream()
+#endif
+
 #ifdef HAVE_CXX11_ATOMIC
 #define SOME_KIND_OF_LOG_EVERY_N(severity, n, what_to_do) \
   static std::atomic<int> LOG_OCCURRENCES(0), LOG_OCCURRENCES_MOD_N(0); \
@@ -1159,6 +1219,8 @@ GOOGLE_GLOG_DLL_DECL bool IsFailureSignalHandlerInstalled();
 #define LOG_EVERY_N(severity, n)                                        \
   SOME_KIND_OF_LOG_EVERY_N(severity, (n), @ac_google_namespace@::LogMessage::SendToLog)
 
+#define LOG_EVERY_T(severity, T) SOME_KIND_OF_LOG_EVERY_T(severity, (T))
+
 #define SYSLOG_EVERY_N(severity, n) \
   SOME_KIND_OF_LOG_EVERY_N(severity, (n), @ac_google_namespace@::LogMessage::SendToSyslogAndLog)
 

src/googletest.h

@@ -118,6 +118,15 @@ void InitGoogleTest(int*, char**) {}
 
 // The following is some bare-bones testing infrastructure
 
+#define EXPECT_NEAR(val1, val2, abs_error)                                     \
+  do {                                                                         \
+    if (abs(val1 - val2) > abs_error) {                                        \
+      fprintf(stderr, "Check failed: %s within %s of %s\n", #val1, #abs_error, \
+              #val2);                                                          \
+      exit(1);                                                                 \
+    }                                                                          \
+  } while (0)
+
 #define EXPECT_TRUE(cond)                               \
   do {                                                  \
     if (!(cond)) {                                      \

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,96 @@ static void TestCustomLoggerDeletionOnShutdown() {
   EXPECT_FALSE(IsGoogleLoggingInitialized());
 }
 
+namespace LogTimes {
+// 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 5% (500us or 0.5ms)
+GLOG_CONSTEXPR int64_t LOG_PERIOD_NS     = 10000000;  // 10ms
+GLOG_CONSTEXPR int64_t LOG_PERIOD_TOL_NS = 500000;    // 500us
+
+// 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.
+GLOG_CONSTEXPR size_t MAX_CALLS = 10;
+}  // namespace LogStreamTimes
+
+#ifdef HAVE_CXX11_CHRONO
+struct LogTimeRecorder {
+  size_t m_streamTimes = 0;
+  std::chrono::steady_clock::time_point m_callTimes[LogTimes::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, LogTimeRecorder& t) {
+  t.m_callTimes[t.m_streamTimes++] = std::chrono::steady_clock::now();
+  return stream;
+}
+// get elapsed time in nanoseconds
+int64 elapsedTime_ns(const std::chrono::steady_clock::time_point& begin,
+        const std::chrono::steady_clock::time_point& end) {
+  return std::chrono::duration_cast<std::chrono::nanoseconds>((end - begin))
+          .count();
+}
+#elif defined(OS_WINDOWS)
+struct LogTimeRecorder {
+  size_t m_streamTimes = 0;
+  LARGE_INTEGER m_callTimes[LogTimes::MAX_CALLS];
+};
+std::ostream& operator<<(std::ostream& stream, LogTimeRecorder& t) {
+  QueryPerformanceCounter(&t.m_callTimes[t.m_streamTimes++]);
+  return stream;
+}
+// get elapsed time in nanoseconds
+int64 elapsedTime_ns(const LARGE_INTEGER& begin, const LARGE_INTEGER& end) {
+  LARGE_INTEGER freq;
+  QueryPerformanceFrequency(&freq);
+  return (end.QuadPart - begin.QuadPart) * 1000000000 / freq.QuadPart;
+}
+#else
+struct LogTimeRecorder {
+  size_t m_streamTimes = 0;
+  timespec m_callTimes[LogTimes::MAX_CALLS];
+};
+std::ostream& operator<<(std::ostream& stream, LogTimeRecorder& t) {
+  clock_gettime(CLOCK_MONOTONIC, &t.m_callTimes[t.m_streamTimes++]);
+  return stream;
+}
+// get elapsed time in nanoseconds
+int64 elapsedTime_ns(const timespec& begin, const timespec& end) {
+  return (end.tv_sec - begin.tv_sec) * 1000000000 +
+         (end.tv_nsec - begin.tv_nsec);
+}
+#endif
+
+static void TestLogPeriodically() {
+  fprintf(stderr, "==== Test log periodically\n");
+
+  LogTimeRecorder timeLogger;
+
+  GLOG_CONSTEXPR double LOG_PERIOD_SEC = LogTimes::LOG_PERIOD_NS / 1000000000.0;
+
+  while (timeLogger.m_streamTimes < LogTimes::MAX_CALLS) {
+        LOG_EVERY_T(INFO, LOG_PERIOD_SEC)
+            << timeLogger << "Timed Message #" << timeLogger.m_streamTimes;
+  }
+
+  // Calculate time between each call in nanoseconds for higher resolution to
+  // minimize error.
+  int64 nsBetweenCalls[LogTimes::MAX_CALLS - 1];
+  for (size_t i = 1; i < LogTimes::MAX_CALLS; ++i) {
+    nsBetweenCalls[i - 1] = elapsedTime_ns(
+            timeLogger.m_callTimes[i - 1], timeLogger.m_callTimes[i]);
+  }
+
+  for (size_t idx = 0; idx < LogTimes::MAX_CALLS - 1; ++idx) {
+    int64 time_ns = nsBetweenCalls[idx];
+    EXPECT_NEAR(time_ns, LogTimes::LOG_PERIOD_NS, LogTimes::LOG_PERIOD_TOL_NS);
+  }
+}
+
 _START_GOOGLE_NAMESPACE_
 namespace glog_internal_namespace_ {
 extern  // in logging.cc