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

diff --git a/folly/Logging.h b/folly/Logging.h
index 788a69dbaf128b1eebf0da1b35affc0cf7117c13..488132b98eaeba92e2d6258195c18fa9982d6314 100644 (file)
--- 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 (file)
index 0000000..d84b641
--- /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();
+}