XLOG_EVERY_N, XLOG_EVERY_N_EXACT

Summary: [Folly] `XLOG_EVERY_N`, `XLOG_EVERY_N_EXACT`. Renaming `XLOG_EVERY_N` to `XLOG_EVERY_N_EXACT` and adding a new `XLOG_EVERY_N` which performs better under contention, at the cost of possibly missing increments and therefore over-logging.

Reviewed By: simpkins

Differential Revision: D15230953

fbshipit-source-id: cf7b86b96340f78156f7cd25f7e784b0f1b8d5fa

folly/logging/test/XlogBench.cpp

+/*
+ * Copyright 2019-present 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/xlog.h>
+
+#include <cstddef>
+#include <thread>
+
+#include <boost/thread/barrier.hpp>
+
+#include <folly/Benchmark.h>
+#include <folly/init/Init.h>
+#include <folly/logging/Init.h>
+#include <folly/logging/LogConfig.h>
+#include <folly/logging/LogConfigParser.h>
+#include <folly/logging/LogHandler.h>
+#include <folly/logging/LogHandlerConfig.h>
+#include <folly/logging/LogHandlerFactory.h>
+#include <folly/portability/GFlags.h>
+
+DEFINE_int32(num_threads, 4, "Number of threads performing logging");
+DEFINE_int32(every_n, 1 << 10, "Inverse frequency for every-n logging");
+
+namespace folly {
+
+// a noop which the compiler cannot see through
+// used to prevent some compiler optimizations which could skew benchmarks
+[[gnu::weak]] void noop() noexcept {}
+
+namespace {
+class NullHandler : public LogHandler {
+ public:
+  void handleMessage(const LogMessage&, const LogCategory*) override {}
+  void flush() override {}
+  LogHandlerConfig getConfig() const override {
+    return LogHandlerConfig{""};
+  }
+};
+class NullHandlerFactory : public LogHandlerFactory {
+ public:
+  StringPiece getType() const override {
+    return "null";
+  }
+  std::shared_ptr<LogHandler> createHandler(const Options&) override {
+    return std::make_shared<NullHandler>();
+  }
+};
+} // namespace
+
+template <typename XlogEvery>
+void runXlogEveryNBench(size_t iters, XlogEvery func) {
+  BenchmarkSuspender braces;
+
+  boost::barrier barrier(1 + FLAGS_num_threads);
+
+  std::vector<std::thread> threads(FLAGS_num_threads);
+
+  for (auto& thread : threads) {
+    thread = std::thread([&] {
+      auto once = [&] {
+        noop();
+        func();
+      };
+
+      // in case the first call does expensive setup, such as take a global lock
+      once();
+
+      barrier.wait(); // A - wait for thread start
+
+      barrier.wait(); // B - init the work
+
+      for (auto i = 0u; i < iters; ++i) {
+        once();
+      }
+
+      barrier.wait(); // C - join the work
+    });
+  }
+
+  barrier.wait(); // A - wait for thread start
+
+  // we want to exclude thread start/stop operations from measurement
+  braces.dismissing([&] {
+    barrier.wait(); // B - init the work
+    barrier.wait(); // C - join the work
+  });
+
+  for (auto& thread : threads) {
+    thread.join();
+  }
+}
+
+BENCHMARK(xlog_every_n, iters) {
+  runXlogEveryNBench(iters, [] { //
+    XLOG_EVERY_N(INFO, FLAGS_every_n, "hi");
+  });
+}
+
+BENCHMARK(xlog_every_n_exact, iters) {
+  runXlogEveryNBench(iters, [] { //
+    XLOG_EVERY_N_EXACT(INFO, FLAGS_every_n, "hi");
+  });
+}
+} // namespace folly
+
+FOLLY_INIT_LOGGING_CONFIG(".=INFO:default; default=null");
+
+int main(int argc, char** argv) {
+  folly::LoggerDB::get().registerHandlerFactory(
+      std::make_unique<folly::NullHandlerFactory>(),
+      /* replaceExisting = */ true);
+  folly::Init init(&argc, &argv);
+  folly::runBenchmarks();
+  return 0;
+}

folly/logging/test/XlogTest.cpp

@@ -294,6 +294,23 @@ TEST_F(XlogTest, rateLimiting) {
           "msg 49"));
   handler->clearMessages();
 
+  // Test XLOG_EVERY_N_EXACT
+  for (size_t n = 0; n < 50; ++n) {
+    XLOG_EVERY_N_EXACT(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) {

folly/logging/xlog.h

@@ -114,14 +114,40 @@
 
 /**
  * Similar to XLOG(...) except only log a message every @param n
- * invocations.
+ * invocations, approximately.
  *
- * The internal counter is process-global and threadsafe.
+ * The internal counter is process-global and threadsafe but, to
+ * to avoid the performance degradation of atomic-rmw operations,
+ * increments are non-atomic. Some increments may be missed under
+ * contention, leading to possible over-logging or under-logging
+ * effects.
  */
 #define XLOG_EVERY_N(level, n, ...)                                        \
   XLOG_IF(                                                                 \
       level,                                                               \
-      [] {                                                                     \
+      []() FOLLY_EXPORT -> bool {                                          \
+        static std::atomic<size_t> folly_detail_xlog_count{0};             \
+        auto const folly_detail_xlog_count_value =                         \
+            folly_detail_xlog_count.load(std::memory_order_relaxed);       \
+        folly_detail_xlog_count.store(                                     \
+            folly_detail_xlog_count_value + 1, std::memory_order_relaxed); \
+        return FOLLY_UNLIKELY((folly_detail_xlog_count_value % (n)) == 0); \
+      }(),                                                                 \
+      ##__VA_ARGS__)
+
+/**
+ * Similar to XLOG(...) except only log a message every @param n
+ * invocations, exactly.
+ *
+ * The internal counter is process-global and threadsafe and
+ * increments are atomic. The over-logging and under-logging
+ * schenarios of XLOG_EVERY_N(...) are avoided, traded off for
+ * the performance degradation of atomic-rmw operations.
+ */
+#define XLOG_EVERY_N_EXACT(level, n, ...)                                      \
+  XLOG_IF(                                                                     \
+      level,                                                                   \
+      []() FOLLY_EXPORT -> bool {                                              \
         static std::atomic<size_t> folly_detail_xlog_count{0};                 \
         return FOLLY_UNLIKELY(                                                 \
             (folly_detail_xlog_count.fetch_add(1, std::memory_order_relaxed) % \