logging: Add rate limiting log macros

Summary:
This adds several macros for explicitly rate-limited log messages.

- `XLOG_EVERY_N()` logs only 1 of every N times it is called.
  This is similar to glog's `LOG_EVERY_N()` and `VLOG_EVERY_N()` macros.

- `XLOG_EVERY_MS()` logs only once per specified time interval.
  This is similar to the `LOG_EVERY_MS()` and `LOG_EVERY_MS_ATOMIC()` macros
  that Facebook has defined internally on top of glog.

- `XLOG_N_PER_MS()` logs the first N messages per specified time interval.

These should make it easier for Facebook programs to migrate from glog to
xlog.

Reviewed By: yfeldblum

Differential Revision: D8218663

fbshipit-source-id: a1e71265ace41fea95e5dbb79bc4381962b11297

folly/logging/test/TestLogHandler.cpp

@@ -19,6 +19,15 @@
 
 namespace folly {
 
+std::vector<std::string> TestLogHandler::getMessageValues() {
+  std::vector<std::string> values;
+  values.reserve(messages_.size());
+  for (const auto& msgInfo : messages_) {
+    values.push_back(msgInfo.first.getMessage());
+  }
+  return values;
+}
+
 std::shared_ptr<LogHandler> TestLogHandlerFactory::createHandler(
     const Options& options) {
   return std::make_shared<TestLogHandler>(LogHandlerConfig{type_, options});

folly/logging/test/TestLogHandler.h

@@ -45,6 +45,11 @@ class TestLogHandler : public LogHandler {
     return messages_;
   }
 
+  std::vector<std::string> getMessageValues();
+  void clearMessages() {
+    messages_.clear();
+  }
+
   void handleMessage(
       const LogMessage& message,
       const LogCategory* handlerCategory) override {

folly/logging/test/XlogTest.cpp

@@ -23,11 +23,17 @@
 #include <folly/logging/test/XlogHeader1.h>
 #include <folly/logging/test/XlogHeader2.h>
 #include <folly/portability/Constexpr.h>
+#include <folly/portability/GMock.h>
 #include <folly/portability/GTest.h>
 #include <folly/test/TestUtils.h>
+#include <chrono>
+#include <thread>
 
 using namespace folly;
 using std::make_shared;
+using testing::ElementsAre;
+using testing::ElementsAreArray;
+using namespace std::chrono_literals;
 
 XLOG_SET_CATEGORY_NAME("xlog_test.main_file")
 
@@ -266,6 +272,69 @@ TEST_F(XlogTest, perFileCategoryHandling) {
   messages.clear();
 }
 
+TEST_F(XlogTest, rateLimiting) {
+  auto handler = make_shared<TestLogHandler>();
+  LoggerDB::get().getCategory("xlog_test")->addHandler(handler);
+  LoggerDB::get().setLevel("xlog_test", LogLevel::DBG1);
+
+  // Test XLOG_EVERY_N
+  for (size_t n = 0; n < 50; ++n) {
+    XLOG_EVERY_N(DBG1, 7, "msg ", n);
+  }
+  EXPECT_THAT(
+      handler->getMessageValues(),
+      ElementsAre(
+          "msg 0",
+          "msg 7",
+          "msg 14",
+          "msg 21",
+          "msg 28",
+          "msg 35",
+          "msg 42",
+          "msg 49"));
+  handler->clearMessages();
+
+  // Test XLOG_EVERY_MS and XLOG_N_PER_MS
+  // We test these together to minimize the number of sleep operations.
+  for (size_t n = 0; n < 10; ++n) {
+    // Integer arguments are treated as millisecond
+    XLOG_EVERY_MS(DBG1, 100, "int arg ", n);
+    // Other duration arguments also work, as long as they are
+    // coarser than milliseconds
+    XLOG_EVERY_MS(DBG1, 100ms, "ms arg ", n);
+    XLOG_EVERY_MS(DBG1, 1s, "s arg ", n);
+
+    // Use XLOG_N_PER_MS() too
+    XLOG_N_PER_MS(DBG1, 2, 100, "2x int arg ", n);
+    XLOG_N_PER_MS(DBG1, 1, 100ms, "1x ms arg ", n);
+    XLOG_N_PER_MS(DBG1, 3, 1s, "3x s arg ", n);
+
+    // Sleep for 100ms between iterations 5 and 6
+    if (n == 5) {
+      /* sleep override */ std::this_thread::sleep_for(110ms);
+    }
+  }
+  EXPECT_THAT(
+      handler->getMessageValues(),
+      ElementsAreArray({
+          "int arg 0",
+          "ms arg 0",
+          "s arg 0",
+          "2x int arg 0",
+          "1x ms arg 0",
+          "3x s arg 0",
+          "2x int arg 1",
+          "3x s arg 1",
+          "3x s arg 2",
+          "int arg 6",
+          "ms arg 6",
+          "2x int arg 6",
+          "1x ms arg 6",
+          "2x int arg 7",
+      }));
+  handler->clearMessages();
+}
+
 TEST_F(XlogTest, getXlogCategoryName) {
   EXPECT_EQ("foo.cpp", getXlogCategoryNameForFile("foo.cpp"));
   EXPECT_EQ("foo.h", getXlogCategoryNameForFile("foo.h"));

folly/logging/xlog.h

@@ -21,6 +21,7 @@
 #include <folly/logging/LogStream.h>
 #include <folly/logging/Logger.h>
 #include <folly/logging/LoggerDB.h>
+#include <folly/logging/RateLimiter.h>
 #include <cstdlib>
 
 /*
@@ -86,6 +87,54 @@
       arg1,                                   \
       ##__VA_ARGS__)
 
+/**
+ * Similar to XLOG(...) except only log a message every @param ms
+ * milliseconds.
+ *
+ * Note that this is threadsafe.
+ */
+#define XLOG_EVERY_MS(level, ms, ...)                                    \
+  XLOG_IF(                                                               \
+      level,                                                             \
+      [] {                                                               \
+        static ::folly::logging::IntervalRateLimiter                     \
+            folly_detail_xlog_limiter(1, std::chrono::milliseconds(ms)); \
+        return folly_detail_xlog_limiter.check();                        \
+      }(),                                                               \
+      ##__VA_ARGS__)
+
+/**
+ * Similar to XLOG(...) except only log a message every @param n
+ * invocations.
+ *
+ * The internal counter is process-global and threadsafe.
+ */
+#define XLOG_EVERY_N(level, n, ...)                                            \
+  XLOG_IF(                                                                     \
+      level,                                                                   \
+      [] {                                                                     \
+        static std::atomic<size_t> folly_detail_xlog_count{0};                 \
+        return FOLLY_UNLIKELY(                                                 \
+            (folly_detail_xlog_count.fetch_add(1, std::memory_order_relaxed) % \
+             (n)) == 0);                                                       \
+      }(),                                                                     \
+      ##__VA_ARGS__)
+
+/**
+ * Similar to XLOG(...) except only log at most @param count messages
+ * per @param ms millisecond interval.
+ *
+ * The internal counters are process-global and threadsafe.
+ */
+#define XLOG_N_PER_MS(level, count, ms, ...)                                   \
+  XLOG_IF(                                                                     \
+      level,                                                                   \
+      [] {                                                                     \
+        static ::folly::logging::IntervalRateLimiter                           \
+            folly_detail_xlog_limiter((count), std::chrono::milliseconds(ms)); \
+        return folly_detail_xlog_limiter.check();                              \
+      }(),                                                                     \
+      ##__VA_ARGS__)
 /**
  * FOLLY_XLOG_STRIP_PREFIXES can be defined to a string containing a
  * colon-separated list of directory prefixes to strip off from the filename