Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
30 changes: 30 additions & 0 deletions source/common/common/logger.h
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
#pragma once

#include <bitset>
#include <cstdint>
#include <memory>
#include <string>
Expand Down Expand Up @@ -400,6 +401,35 @@ template <Id id> class Loggable {
} \
} while (0)

#define ENVOY_LOG_FIRST_N(LEVEL, N, ...) \
do { \
static auto* countdown = new std::atomic<uint64_t>(); \
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This isn't thread-safe. If two threads do this at the same time, there could be a leak. I think this ends up being better as static std::atomic<uint64_t> countdown;. Either the compiler will see that it is initialized by zeroing, and do so at program start, or it will double-zero the same memory by initializing multiple times, but should avoid a leak at least.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wouldn't that lead up to a potential deinitialization fiasco? I was following the lead of

#define CONSTRUCT_ON_FIRST_USE(type, ...) \

Reading up I am led to believe this would be thread safe since c++ 11 but I can't find a source that I would consider authorative,. Will dig some more.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Relevant on the subject of leaking and stack vs heap allocation in the construct on first use idiom: Why doesn’t the Construct On First Use Idiom use a static object instead of a static pointer?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

https://en.cppreference.com/w/cpp/language/storage_duration#Static_local_variables has:

If multiple threads attempt to initialize the same static local variable concurrently, the initialization occurs exactly once (similar behavior can be obtained for arbitrary functions with std::call_once). Note: usual implementations of this feature use variants of the double-checked locking pattern, which reduces runtime overhead for already-initialized local statics to a single non-atomic boolean comparison.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Did some reading, and you're correct. TIL something new about static initialization.

if (countdown->fetch_add(1) < N) { \
ENVOY_LOG(LEVEL, ##__VA_ARGS__); \
} \
} while (0)

#define ENVOY_LOG_ONCE(LEVEL, ...) \
do { \
ENVOY_LOG_FIRST_N(LEVEL, 1, ##__VA_ARGS__); \
} while (0)

#define ENVOY_LOG_EVERY_NTH(LEVEL, N, ...) \
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As per earlier discussion, every Pow2 could be good as well.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh yes good catch, my intent was actually to add that. Will do.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done, added ENVOY_LOG_WITH_BACKOFF in 371fa5d + tests

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

/cc @ggreenway ^^

do { \
static auto* count = new std::atomic<uint64_t>(); \
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<uint64_t>(); \
if (std::bitset<64>(1 + count->fetch_add(1)).count() == 1) { \
ENVOY_LOG(LEVEL, ##__VA_ARGS__); \
} \
} while (0)

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

Expand All @@ -8,6 +9,7 @@
#include "test/mocks/network/mocks.h"
#include "test/test_common/logging.h"

#include "absl/synchronization/barrier.h"
#include "gmock/gmock.h"
#include "gtest/gtest.h"

Expand Down Expand Up @@ -118,6 +120,78 @@ TEST(Logger, checkLoggerLevel) {
EXPECT_THAT(test_obj.executeAtTraceLevel(), testing::Eq(2));
}

void spamCall(std::function<void()>&& call_to_spam, const uint32_t num_threads) {
std::vector<std::thread> threads(num_threads);
auto barrier = std::make_unique<absl::Barrier>(num_threads);

for (auto& thread : threads) {
thread = std::thread([&call_to_spam, &barrier] {
// Allow threads to accrue, to maximize concurrency on the call we are testing.
if (barrier->Block()) {
barrier.reset();
}
call_to_spam();
});
}
for (std::thread& thread : threads) {
thread.join();
}
}

TEST(Logger, SparseLogMacros) {
class SparseLogMacrosTestHelper : public Logger::Loggable<Logger::Id::filter> {
public:
SparseLogMacrosTestHelper() { ENVOY_LOGGER().set_level(spdlog::level::info); }
void logSomething() { ENVOY_LOG_ONCE(error, "foo1 '{}'", evaluations()++); }
void logSomethingElse() { ENVOY_LOG_ONCE(error, "foo2 '{}'", evaluations()++); }
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 logEveryPow2() { ENVOY_LOG_EVERY_POW_2(error, "foo6 '{}'", evaluations()++); }
std::atomic<int32_t>& evaluations() { MUTABLE_CONSTRUCT_ON_FIRST_USE(std::atomic<int32_t>); };
};
constexpr uint32_t kNumThreads = 100;
SparseLogMacrosTestHelper helper;
spamCall(
[&helper]() {
helper.logSomething();
helper.logSomething();
},
kNumThreads);
EXPECT_EQ(1, helper.evaluations());
spamCall(
[&helper]() {
helper.logSomethingElse();
helper.logSomethingElse();
},
kNumThreads);
// Two distinct log lines ought to result in two evaluations, and no more.
EXPECT_EQ(2, helper.evaluations());

spamCall([&helper]() { helper.logSomethingThrice(); }, kNumThreads);
// Single log line should be emitted 3 times.
EXPECT_EQ(5, helper.evaluations());

spamCall([&helper]() { helper.logEverySeventh(); }, kNumThreads);
// (100 threads / log every 7th) + 1s = 15 more evaluations upon logging very 7th.
EXPECT_EQ(20, helper.evaluations());

helper.logEveryPow2();
// First call ought to propagate.
EXPECT_EQ(21, helper.evaluations());

spamCall([&helper]() { helper.logEveryPow2(); }, 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() ? 28 : 27, helper.evaluations());
}

TEST(RegistryTest, LoggerWithName) {
EXPECT_EQ(nullptr, Logger::Registry::logger("blah"));
EXPECT_EQ("upstream", Logger::Registry::logger("upstream")->name());
Expand Down