Skip to content

Commit

Permalink
Add ENVOY_LOG_PERIODIC
Browse files Browse the repository at this point in the history
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 <oschaaf@we-amp.com>
  • Loading branch information
oschaaf committed Sep 2, 2020
1 parent f1c0031 commit 42a4eba
Show file tree
Hide file tree
Showing 2 changed files with 33 additions and 1 deletion.
17 changes: 17 additions & 0 deletions source/common/common/logger.h
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
#pragma once

#include <bitset>
#include <chrono>
#include <cstdint>
#include <memory>
#include <string>
Expand Down Expand Up @@ -430,6 +431,22 @@ 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, ...) \
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)) { \
ENVOY_LOG(LEVEL, ##__VA_ARGS__); \
} \
} while (0)

#define ENVOY_FLUSH_LOG() \
do { \
if (Envoy::Logger::Context::useFancyLogger()) { \
Expand Down
17 changes: 16 additions & 1 deletion test/common/common/log_macros_test.cc
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
#include <chrono>
#include <functional>
#include <iostream>
#include <string>
Expand All @@ -15,6 +16,8 @@

namespace Envoy {

using namespace std::chrono_literals;

class TestFilterLog : public Logger::Loggable<Logger::Id::filter> {
public:
void logMessage() {
Expand Down Expand Up @@ -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<int32_t>& evaluations() { MUTABLE_CONSTRUCT_ON_FIRST_USE(std::atomic<int32_t>); };
};
constexpr uint32_t kNumThreads = 100;
Expand Down Expand Up @@ -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) {
Expand Down

0 comments on commit 42a4eba

Please sign in to comment.