From 0a52fd7bf776aad7b217f16039a6d12f673c9f69 Mon Sep 17 00:00:00 2001
From: Nathan Bronson <ngbronson@fb.com>
Date: Thu, 27 Feb 2014 09:32:50 -0800
Subject: [PATCH] make FB_LOG_EVERY_MS thread safe

Summary:
Use compare_exchange_strong to update the previous time so that
there is no race.  This diff also adds microbenchmarks.

Test Plan: unit tests

Reviewed By: andrei.alexandrescu@fb.com

FB internal diff: D1191217
---
 folly/Logging.h            | 29 ++++++++++++++++++-----------
 folly/test/LoggingTest.cpp | 37 ++++++++++++++++++++++++++++++++++++-
 2 files changed, 54 insertions(+), 12 deletions(-)

diff --git a/folly/Logging.h b/folly/Logging.h
index 488132b9..0c34de24 100644
--- a/folly/Logging.h
+++ b/folly/Logging.h
@@ -17,6 +17,7 @@
 #ifndef FOLLY_LOGGING_H_
 #define FOLLY_LOGGING_H_
 
+#include <atomic>
 #include <chrono>
 #include <glog/logging.h>
 
@@ -29,18 +30,24 @@
  *   " since you last saw this.";
  *
  * The implementation uses for statements to introduce variables in
- * a nice way that doesn't mess surrounding statements.
+ * a nice way that doesn't mess surrounding statements.  It is thread
+ * safe.
  */
-#define FB_LOG_EVERY_MS(severity, milli_interval)                       \
-  for (bool FB_LEM_once = true; FB_LEM_once; )                          \
-    for (const auto FB_LEM_now = ::std::chrono::system_clock::now();    \
-         FB_LEM_once; )                                                 \
-      for (static ::std::chrono::system_clock::time_point FB_LEM_last;  \
-            FB_LEM_once; FB_LEM_once = false)                           \
-        if (FB_LEM_now - FB_LEM_last <                                  \
-            ::std::chrono::milliseconds(milli_interval)) {              \
-        } else                                                          \
-          (FB_LEM_last = FB_LEM_now, LOG(severity))
+#define FB_LOG_EVERY_MS(severity, milli_interval)                            \
+  for (bool FB_LEM_once = true; FB_LEM_once; )                               \
+    for (::std::chrono::milliseconds::rep FB_LEM_prev, FB_LEM_now =          \
+             ::std::chrono::duration_cast< ::std::chrono::milliseconds>(     \
+                 ::std::chrono::system_clock::now().time_since_epoch()       \
+                 ).count();                                                  \
+         FB_LEM_once; )                                                      \
+      for (static ::std::atomic< ::std::chrono::milliseconds::rep>           \
+               FB_LEM_hist; FB_LEM_once; FB_LEM_once = false)                \
+        if (FB_LEM_now - (FB_LEM_prev =                                      \
+                          FB_LEM_hist.load(std::memory_order_acquire)) <     \
+                milli_interval ||                                            \
+            !FB_LEM_hist.compare_exchange_strong(FB_LEM_prev, FB_LEM_now)) { \
+        } else                                                               \
+          LOG(severity)
 
 #endif
 
diff --git a/folly/test/LoggingTest.cpp b/folly/test/LoggingTest.cpp
index d84b6414..cb45d797 100644
--- a/folly/test/LoggingTest.cpp
+++ b/folly/test/LoggingTest.cpp
@@ -17,6 +17,7 @@
 #include <folly/Logging.h>
 #include <gflags/gflags.h>
 #include <gtest/gtest.h>
+#include <folly/Benchmark.h>
 #include <vector>
 
 TEST(LogEveryMs, basic) {
@@ -39,8 +40,42 @@ TEST(LogEveryMs, basic) {
   EXPECT_TRUE(atLeastOneIsGood);
 }
 
+BENCHMARK(skip_overhead, iter) {
+  auto prev = FLAGS_minloglevel;
+  FLAGS_minloglevel = 2;
+
+  for (unsigned i = 0; i < iter; ++i) {
+    FB_LOG_EVERY_MS(INFO, 1000) << "every 1s";
+  }
+
+  FLAGS_minloglevel = prev;
+}
+
+BENCHMARK(dev_null_log_overhead, iter) {
+  auto prev = FLAGS_minloglevel;
+  FLAGS_minloglevel = 2;
+
+  for (unsigned i = 0; i < iter; ++i) {
+    FB_LOG_EVERY_MS(INFO, -1) << "every -1ms";
+  }
+
+  FLAGS_minloglevel = prev;
+}
+
+// ============================================================================
+// folly/test/LoggingTest.cpp                      relative  time/iter  iters/s
+// ============================================================================
+// skip_overhead                                               36.37ns   27.49M
+// dev_null_log_overhead                                        2.61us  382.57K
+// ============================================================================
+
 int main(int argc, char** argv) {
   testing::InitGoogleTest(&argc, argv);
   google::ParseCommandLineFlags(&argc, &argv, true);
-  return RUN_ALL_TESTS();
+
+  auto rv = RUN_ALL_TESTS();
+  if (!rv && FLAGS_benchmark) {
+    folly::runBenchmarks();
+  }
+  return rv;
 }
-- 
2.34.1