From 42a4eba3c69e17637cc18ef6b3da553abf11926c Mon Sep 17 00:00:00 2001 From: Otto van der Schaaf Date: Thu, 3 Sep 2020 00:36:08 +0200 Subject: [PATCH 1/6] Add ENVOY_LOG_PERIODIC Follow up to #12830 with another sparse log variant. The periodic version relies on a real world time source, which can be discussed separately here. Signed-off-by: Otto van der Schaaf --- source/common/common/logger.h | 17 +++++++++++++++++ test/common/common/log_macros_test.cc | 17 ++++++++++++++++- 2 files changed, 33 insertions(+), 1 deletion(-) diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 8e1bed6412420..2390dad83786e 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -1,6 +1,7 @@ #pragma once #include +#include #include #include #include @@ -430,6 +431,22 @@ template 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, ...) \ + do { \ + static auto* last_hit = new std::atomic(); \ + auto last = last_hit->load(); \ + const auto now = t_logclock::now().time_since_epoch().count(); \ + if ((now - last) > \ + std::chrono::duration_cast(CHRONO_DURATION).count() && \ + last_hit->compare_exchange_strong(last, now)) { \ + ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + } \ + } while (0) + #define ENVOY_FLUSH_LOG() \ do { \ if (Envoy::Logger::Context::useFancyLogger()) { \ diff --git a/test/common/common/log_macros_test.cc b/test/common/common/log_macros_test.cc index 84a2cd79b4961..e6742c5d47907 100644 --- a/test/common/common/log_macros_test.cc +++ b/test/common/common/log_macros_test.cc @@ -1,3 +1,4 @@ +#include #include #include #include @@ -15,6 +16,8 @@ namespace Envoy { +using namespace std::chrono_literals; + class TestFilterLog : public Logger::Loggable { public: void logMessage() { @@ -148,6 +151,7 @@ TEST(Logger, SparseLogMacros) { void logSomethingThrice() { ENVOY_LOG_FIRST_N(error, 3, "foo4 '{}'", evaluations()++); } void logEverySeventh() { ENVOY_LOG_EVERY_NTH(error, 7, "foo5 '{}'", evaluations()++); } void logEveryPow2() { ENVOY_LOG_EVERY_POW_2(error, "foo6 '{}'", evaluations()++); } + void logEverySecond() { ENVOY_LOG_PERIODIC(error, 1s, "foo6 '{}'", evaluations()++); } std::atomic& evaluations() { MUTABLE_CONSTRUCT_ON_FIRST_USE(std::atomic); }; }; constexpr uint32_t kNumThreads = 100; @@ -185,11 +189,22 @@ TEST(Logger, SparseLogMacros) { // 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.logEverySecond(); }, kNumThreads); + // First call ought to evaluate. + EXPECT_EQ(28, helper.evaluations()); + + // 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. + sleep(1); + spamCall([&helper]() { helper.logEverySecond(); }, kNumThreads); + EXPECT_EQ(29, 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() ? 28 : 27, helper.evaluations()); + EXPECT_EQ(::Envoy::Logger::Context::useFancyLogger() ? 30 : 29, helper.evaluations()); } TEST(RegistryTest, LoggerWithName) { From 85003d494b498d85dbc1bd49bbffa94c7e37d61e Mon Sep 17 00:00:00 2001 From: Otto van der Schaaf Date: Fri, 4 Sep 2020 14:12:20 +0200 Subject: [PATCH 2/6] Review feedback Signed-off-by: Otto van der Schaaf --- source/common/common/logger.h | 43 ++++++++++++++++----------- test/common/common/log_macros_test.cc | 5 ++-- 2 files changed, 28 insertions(+), 20 deletions(-) diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 2390dad83786e..cdeea32f87080 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -404,9 +404,11 @@ template class Loggable { #define ENVOY_LOG_FIRST_N(LEVEL, N, ...) \ do { \ - static auto* countdown = new std::atomic(); \ - if (countdown->fetch_add(1) < N) { \ - ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ + static auto* countdown = new std::atomic(); \ + if (countdown->fetch_add(1) < N) { \ + ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + } \ } \ } while (0) @@ -417,33 +419,40 @@ template class Loggable { #define ENVOY_LOG_EVERY_NTH(LEVEL, N, ...) \ do { \ - static auto* count = new std::atomic(); \ - if ((count->fetch_add(1) % N) == 0) { \ - ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ + static auto* count = new std::atomic(); \ + if ((count->fetch_add(1) % N) == 0) { \ + ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + } \ } \ } while (0) #define ENVOY_LOG_EVERY_POW_2(LEVEL, ...) \ do { \ - static auto* count = new std::atomic(); \ - if (std::bitset<64>(1 + count->fetch_add(1)).count() == 1) { \ - ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ + static auto* count = new std::atomic(); \ + if (std::bitset<64>(1 + count->fetch_add(1)).count() == 1) { \ + ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + } \ } \ } 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. +// We'd have to introduce a singleton for a time source here, and consensus was that avoiding +// that is preferrable. using t_logclock = std::chrono::steady_clock; // NOLINT #define ENVOY_LOG_PERIODIC(LEVEL, CHRONO_DURATION, ...) \ do { \ - static auto* last_hit = new std::atomic(); \ - auto last = last_hit->load(); \ - const auto now = t_logclock::now().time_since_epoch().count(); \ - if ((now - last) > \ - std::chrono::duration_cast(CHRONO_DURATION).count() && \ - last_hit->compare_exchange_strong(last, now)) { \ - ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ + static auto* last_hit = new std::atomic(); \ + auto last = last_hit->load(); \ + const auto now = t_logclock::now().time_since_epoch().count(); \ + if ((now - last) > \ + std::chrono::duration_cast(CHRONO_DURATION).count() && \ + last_hit->compare_exchange_strong(last, now)) { \ + 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 index e6742c5d47907..18642fef7a9ed 100644 --- a/test/common/common/log_macros_test.cc +++ b/test/common/common/log_macros_test.cc @@ -151,7 +151,7 @@ TEST(Logger, SparseLogMacros) { void logSomethingThrice() { ENVOY_LOG_FIRST_N(error, 3, "foo4 '{}'", evaluations()++); } void logEverySeventh() { ENVOY_LOG_EVERY_NTH(error, 7, "foo5 '{}'", evaluations()++); } void logEveryPow2() { ENVOY_LOG_EVERY_POW_2(error, "foo6 '{}'", evaluations()++); } - void logEverySecond() { ENVOY_LOG_PERIODIC(error, 1s, "foo6 '{}'", evaluations()++); } + void logEverySecond() { ENVOY_LOG_PERIODIC(error, 1s, "foo7 '{}'", evaluations()++); } std::atomic& evaluations() { MUTABLE_CONSTRUCT_ON_FIRST_USE(std::atomic); }; }; constexpr uint32_t kNumThreads = 100; @@ -203,8 +203,7 @@ TEST(Logger, SparseLogMacros) { 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() ? 30 : 29, helper.evaluations()); + EXPECT_EQ(29, helper.evaluations()); } TEST(RegistryTest, LoggerWithName) { From aca8716ccf24e098fa385263e6af991f4d27416d Mon Sep 17 00:00:00 2001 From: Otto van der Schaaf Date: Fri, 4 Sep 2020 14:30:40 +0200 Subject: [PATCH 3/6] Amend comment Signed-off-by: Otto van der Schaaf --- source/common/common/logger.h | 2 +- test/common/common/log_macros_test.cc | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/source/common/common/logger.h b/source/common/common/logger.h index cdeea32f87080..e283ad3d42347 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -439,7 +439,7 @@ template class Loggable { // This is to get us to pass the format check. We reference a real-world time source here. // We'd have to introduce a singleton for a time source here, and consensus was that avoiding -// that is preferrable. +// that is preferable. using t_logclock = std::chrono::steady_clock; // NOLINT #define ENVOY_LOG_PERIODIC(LEVEL, CHRONO_DURATION, ...) \ diff --git a/test/common/common/log_macros_test.cc b/test/common/common/log_macros_test.cc index 18642fef7a9ed..30b30f3c2ac2d 100644 --- a/test/common/common/log_macros_test.cc +++ b/test/common/common/log_macros_test.cc @@ -201,8 +201,8 @@ TEST(Logger, SparseLogMacros) { EXPECT_EQ(29, 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. + // We shouldn't observe additional argument evaluations for log lines below the configured + // log level. EXPECT_EQ(29, helper.evaluations()); } From 541e55549964675c6844b9b6e827a7e8f8ce6481 Mon Sep 17 00:00:00 2001 From: Otto van der Schaaf Date: Fri, 4 Sep 2020 17:39:10 +0200 Subject: [PATCH 4/6] Review feedback II Signed-off-by: Otto van der Schaaf --- source/common/common/logger.h | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/source/common/common/logger.h b/source/common/common/logger.h index e283ad3d42347..d6c1c03a373a4 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -405,7 +405,7 @@ template class Loggable { #define ENVOY_LOG_FIRST_N(LEVEL, N, ...) \ do { \ if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ - static auto* countdown = new std::atomic(); \ + static auto* countdown = new std::atomic(); \ if (countdown->fetch_add(1) < N) { \ ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ } \ @@ -420,7 +420,7 @@ template class Loggable { #define ENVOY_LOG_EVERY_NTH(LEVEL, N, ...) \ do { \ if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ - static auto* count = new std::atomic(); \ + static auto* count = new std::atomic(); \ if ((count->fetch_add(1) % N) == 0) { \ ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ } \ @@ -431,7 +431,7 @@ template class Loggable { do { \ if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ static auto* count = new std::atomic(); \ - if (std::bitset<64>(1 + count->fetch_add(1)).count() == 1) { \ + if (std::bitset<64>(1 /* for the first hit*/ + count->fetch_add(1)).count() == 1) { \ ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ } \ } \ @@ -445,7 +445,7 @@ using t_logclock = std::chrono::steady_clock; // NOLINT #define ENVOY_LOG_PERIODIC(LEVEL, CHRONO_DURATION, ...) \ do { \ if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ - static auto* last_hit = new std::atomic(); \ + static auto* last_hit = new std::atomic(); \ auto last = last_hit->load(); \ const auto now = t_logclock::now().time_since_epoch().count(); \ if ((now - last) > \ From 15819e65a36c23e5e6627ec5372dfce97aa2a95d Mon Sep 17 00:00:00 2001 From: Otto van der Schaaf Date: Tue, 8 Sep 2020 22:26:14 +0200 Subject: [PATCH 5/6] review feedback: uint64 where it's not implied Signed-off-by: Otto van der Schaaf --- source/common/common/logger.h | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/source/common/common/logger.h b/source/common/common/logger.h index d6c1c03a373a4..f30dd283e99c1 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -405,7 +405,7 @@ template class Loggable { #define ENVOY_LOG_FIRST_N(LEVEL, N, ...) \ do { \ if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ - static auto* countdown = new std::atomic(); \ + static auto* countdown = new std::atomic(); \ if (countdown->fetch_add(1) < N) { \ ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ } \ @@ -420,7 +420,7 @@ template class Loggable { #define ENVOY_LOG_EVERY_NTH(LEVEL, N, ...) \ do { \ if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ - static auto* count = new std::atomic(); \ + static auto* count = new std::atomic(); \ if ((count->fetch_add(1) % N) == 0) { \ ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ } \ From efbabc5bad8d7f4e0b4a971c63567f3f2542096d Mon Sep 17 00:00:00 2001 From: Otto van der Schaaf Date: Wed, 9 Sep 2020 18:37:56 +0200 Subject: [PATCH 6/6] Fix platform issue, eliminate sleep() call. Signed-off-by: Otto van der Schaaf --- test/common/common/log_macros_test.cc | 3 ++- tools/code_format/check_format.py | 1 + 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/test/common/common/log_macros_test.cc b/test/common/common/log_macros_test.cc index 30b30f3c2ac2d..5625a5f570567 100644 --- a/test/common/common/log_macros_test.cc +++ b/test/common/common/log_macros_test.cc @@ -2,6 +2,7 @@ #include #include #include +#include #include "common/common/fancy_logger.h" #include "common/common/logger.h" @@ -196,7 +197,7 @@ TEST(Logger, SparseLogMacros) { // 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. - sleep(1); + std::this_thread::sleep_for(1s); // NOLINT spamCall([&helper]() { helper.logEverySecond(); }, kNumThreads); EXPECT_EQ(29, helper.evaluations()); diff --git a/tools/code_format/check_format.py b/tools/code_format/check_format.py index 5ac0e628bdcc3..3bd79a37f7276 100755 --- a/tools/code_format/check_format.py +++ b/tools/code_format/check_format.py @@ -37,6 +37,7 @@ "./source/common/event/real_time_system.h", "./source/exe/main_common.cc", "./source/exe/main_common.h", "./source/server/config_validation/server.cc", "./source/common/common/perf_annotation.h", + "./test/common/common/log_macros_test.cc", "./test/test_common/simulated_time_system.cc", "./test/test_common/simulated_time_system.h", "./test/test_common/test_time.cc", "./test/test_common/test_time.h",