Review feedback.

oschaaf · oschaaf · commit 371fa5dffe01 · 2020-08-31T16:57:04.000+02:00
- Back out controversial ENVOY_LOG_PERIODIC, will split that out.
- Don't rely on sleep() in tests
- Add ENVOY_LOG_WITH_BACKOFF

Signed-off-by: Otto van der Schaaf &lt;oschaaf@we-amp.com&gt;
diff --git a/source/common/common/logger.h b/source/common/common/logger.h
@@ -1,6 +1,5 @@
 #pragma once
 
-#include <chrono>
 #include <cstdint>
 #include <memory>
 #include <string>
@@ -422,18 +421,10 @@ template <Id id> class Loggable {
     }                                                                                              \
   } while (0)
 
-// This is to get us to pass the format check. We reference a real-world time source here.
-// I think it's not easy to mock/simulate time here as it stands today anyway.
-using t_logclock = std::chrono::steady_clock; // NOLINT
-
-#define ENVOY_LOG_PERIODIC(LEVEL, CHRONO_DURATION, ...)                                            \
+#define ENVOY_LOG_WITH_BACKOFF(LEVEL, ...)                                                         \
   do {                                                                                             \
-    static auto* last_hit = new std::atomic<uint64_t>();                                           \
-    auto last = last_hit->load();                                                                  \
-    const auto now = t_logclock::now().time_since_epoch().count();                                 \
-    if ((now - last) >                                                                             \
-            std::chrono::duration_cast<std::chrono::nanoseconds>(CHRONO_DURATION).count() &&       \
-        last_hit->compare_exchange_strong(last, now)) {                                            \
+    static auto* count = new std::atomic<uint64_t>();                                              \
+    if (__builtin_popcount(1 + count->fetch_add(1)) == 1) {                                        \
       ENVOY_LOG(LEVEL, ##__VA_ARGS__);                                                             \
     }                                                                                              \
   } while (0)
diff --git a/test/common/common/log_macros_test.cc b/test/common/common/log_macros_test.cc
@@ -1,4 +1,3 @@
-#include <chrono>
 #include <functional>
 #include <future>
 #include <iostream>
@@ -128,15 +127,18 @@ void spamCall(std::function<void()>&& call_to_spam, const uint32_t num_threads)
   std::promise<void> signal_all_threads_running;
   std::shared_future<void> future(signal_all_threads_running.get_future());
 
+  std::atomic<uint32_t> runcount = 0;
   for (auto& thread : threads) {
-    thread = std::thread([future, &call_to_spam] {
+    thread = std::thread([future, &call_to_spam, &runcount] {
+      runcount++;
       future.wait();
       call_to_spam();
     });
   }
   // Allow threads to accrue on future.wait() to maximize concurrency on the call
   // we are testing.
-  sleep(1);
+  while (runcount != num_threads) {
+  }
   signal_all_threads_running.set_value();
   for (std::thread& thread : threads) {
     thread.join();
@@ -152,7 +154,7 @@ TEST(Logger, SparseLogMacros) {
     void logSomethingBelowLogLevelOnce() { ENVOY_LOG_ONCE(debug, "foo3 '{}'", evaluations()++); }
     void logSomethingThrice() { ENVOY_LOG_FIRST_N(error, 3, "foo4 '{}'", evaluations()++); }
     void logEverySeventh() { ENVOY_LOG_EVERY_NTH(error, 7, "foo5 '{}'", evaluations()++); }
-    void logEverySecond() { ENVOY_LOG_PERIODIC(error, 1s, "foo6 '{}'", evaluations()++); }
+    void logWithBackoff() { ENVOY_LOG_WITH_BACKOFF(error, "foo6 '{}'", evaluations()++); }
     std::atomic<int32_t>& evaluations() { MUTABLE_CONSTRUCT_ON_FIRST_USE(std::atomic<int32_t>); };
   };
   constexpr uint32_t kNumThreads = 100;
@@ -181,20 +183,20 @@ TEST(Logger, SparseLogMacros) {
   // (100 threads / log every 7th) + 1s = 15 more evaluations upon logging very 7th.
   EXPECT_EQ(20, helper.evaluations());
 
-  // So use our knowledge that spamCall will sleep 1 second in the following lines:
-  // We expect one log entry / second. Therefore each spamCall ought to result in one
-  // more evaluation. This depends on real time and not sim time, hopefully 1 second
-  // is enough to not introduce flakes in practice.
-  spamCall([&helper]() { helper.logEverySecond(); }, kNumThreads);
+  helper.logWithBackoff();
+  // First call ought to propagate.
   EXPECT_EQ(21, helper.evaluations());
-  spamCall([&helper]() { helper.logEverySecond(); }, kNumThreads);
-  EXPECT_EQ(22, helper.evaluations());
+
+  spamCall([&helper]() { helper.logWithBackoff(); }, kNumThreads);
+  // 64 is the highest power of two that fits when kNumThreads == 100.
+  // We should log on 2, 4, 8, 16, 32, 64, which means we can expect to add 6 more evaluations.
+  EXPECT_EQ(27, helper.evaluations());
 
   spamCall([&helper]() { helper.logSomethingBelowLogLevelOnce(); }, kNumThreads);
   // Without fine-grained logging, we shouldn't observe additional argument evaluations
   // for log lines below the configured log level.
   // TODO(#12885): fancy logger shouldn't always evaluate variadic macro arguments.
-  EXPECT_EQ(::Envoy::Logger::Context::useFancyLogger() ? 23 : 22, helper.evaluations());
+  EXPECT_EQ(::Envoy::Logger::Context::useFancyLogger() ? 28 : 27, helper.evaluations());
 }
 
 TEST(RegistryTest, LoggerWithName) {
