From 6d89f3d33268eaa12d5eb03a4afa5caa856306c5 Mon Sep 17 00:00:00 2001
From: Nathan Bronson <ngbronson@fb.com>
Date: Tue, 4 Feb 2014 12:26:36 -0800
Subject: [PATCH] FB_LOG_EVERY_MS should use wall time instead of cpu time

Summary:
FB_LOG_EVERY_MS was using clock() as its source of time, which
measures the elapsed CPU time of the process.  The name and the docs
suggest that wall time was intended, so that's what this diff does.

Test Plan: new unit test

Reviewed By: andrei.alexandrescu@fb.com

FB internal diff: D1157926
---
 folly/Logging.h            | 21 ++++++++---------
 folly/test/LoggingTest.cpp | 46 ++++++++++++++++++++++++++++++++++++++
 2 files changed, 57 insertions(+), 10 deletions(-)
 create mode 100644 folly/test/LoggingTest.cpp

diff --git a/folly/Logging.h b/folly/Logging.h
index 788a69db..488132b9 100644
--- a/folly/Logging.h
+++ b/folly/Logging.h
@@ -17,7 +17,7 @@
 #ifndef FOLLY_LOGGING_H_
 #define FOLLY_LOGGING_H_
 
-#include <time.h>
+#include <chrono>
 #include <glog/logging.h>
 
 #ifndef FB_LOG_EVERY_MS
@@ -31,15 +31,16 @@
  * The implementation uses for statements to introduce variables in
  * a nice way that doesn't mess surrounding statements.
  */
-#define FB_LOG_EVERY_MS(severity, milliseconds)                         \
-  for (bool LOG_EVERY_MS_once = true; LOG_EVERY_MS_once; )              \
-    for (const ::clock_t LOG_EVERY_MS_now = ::clock(); LOG_EVERY_MS_once; ) \
-      for (static ::clock_t LOG_EVERY_MS_last; LOG_EVERY_MS_once;       \
-           LOG_EVERY_MS_once = false)                                   \
-        if (1000 * (LOG_EVERY_MS_now - LOG_EVERY_MS_last) <             \
-            (milliseconds) * CLOCKS_PER_SEC) {}                         \
-        else                                                            \
-          (LOG_EVERY_MS_last = LOG_EVERY_MS_now, LOG(severity))
+#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))
 
 #endif
 
diff --git a/folly/test/LoggingTest.cpp b/folly/test/LoggingTest.cpp
new file mode 100644
index 00000000..d84b6414
--- /dev/null
+++ b/folly/test/LoggingTest.cpp
@@ -0,0 +1,46 @@
+/*
+ * Copyright 2014 Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include <folly/Logging.h>
+#include <gflags/gflags.h>
+#include <gtest/gtest.h>
+#include <vector>
+
+TEST(LogEveryMs, basic) {
+  std::vector<std::chrono::steady_clock::time_point> hist;
+
+  while (hist.size() < 10) {
+    FB_LOG_EVERY_MS(INFO, 10)
+      << "test msg " << (hist.push_back(std::chrono::steady_clock::now()),
+                         hist.size());
+  }
+
+  bool atLeastOneIsGood = false;
+  for (int i = 0; i < hist.size() - 1; ++i) {
+    auto delta = hist[i + 1] - hist[i];
+    if (delta > std::chrono::milliseconds(5) &&
+        delta < std::chrono::milliseconds(15)) {
+      atLeastOneIsGood = true;
+    }
+  }
+  EXPECT_TRUE(atLeastOneIsGood);
+}
+
+int main(int argc, char** argv) {
+  testing::InitGoogleTest(&argc, argv);
+  google::ParseCommandLineFlags(&argc, &argv, true);
+  return RUN_ALL_TESTS();
+}
-- 
2.34.1