aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorbabenko <babenko@yandex-team.com>2024-10-20 17:04:47 +0300
committerbabenko <babenko@yandex-team.com>2024-10-20 17:19:01 +0300
commite36aa48cf1a20abbfa2a921748f3f1a32b7000be (patch)
tree834cd5cfd04a4c8a80ea24626fa280f420ae5126
parent849246505c7f71dc743ab87a18a4d9a8da1cd1bf (diff)
downloadydb-e36aa48cf1a20abbfa2a921748f3f1a32b7000be.tar.gz
Introduce message_level_overrides to tune log message levels at runtime
* Changelog entry Type: feature Add message_level_overrides option to logging config for better run-time tuning. commit_hash:07e9563fd111c437edf7ac0e5dd190781878d8fa
-rw-r--r--library/cpp/yt/logging/backends/stream/stream_log_manager.cpp6
-rw-r--r--library/cpp/yt/logging/logger-inl.h15
-rw-r--r--library/cpp/yt/logging/logger.h34
-rw-r--r--yt/cpp/mapreduce/interface/logging/yt_log.cpp2
-rw-r--r--yt/yt/core/logging/config.cpp20
-rw-r--r--yt/yt/core/logging/config.h10
-rw-r--r--yt/yt/core/logging/log_manager.cpp50
-rw-r--r--yt/yt/core/logging/unittests/logging_ut.cpp209
8 files changed, 231 insertions, 115 deletions
diff --git a/library/cpp/yt/logging/backends/stream/stream_log_manager.cpp b/library/cpp/yt/logging/backends/stream/stream_log_manager.cpp
index 62269dc0c0..62fa3e91d0 100644
--- a/library/cpp/yt/logging/backends/stream/stream_log_manager.cpp
+++ b/library/cpp/yt/logging/backends/stream/stream_log_manager.cpp
@@ -28,10 +28,8 @@ public:
anchor->Registered = true;
}
- virtual void UpdateAnchor(TLoggingAnchor* anchor) override
- {
- anchor->Enabled = true;
- }
+ virtual void UpdateAnchor(TLoggingAnchor* /*anchor*/) override
+ { }
virtual void Enqueue(TLogEvent&& event) override
{
diff --git a/library/cpp/yt/logging/logger-inl.h b/library/cpp/yt/logging/logger-inl.h
index f3993a4c48..f1be10827f 100644
--- a/library/cpp/yt/logging/logger-inl.h
+++ b/library/cpp/yt/logging/logger-inl.h
@@ -14,11 +14,11 @@ namespace NYT::NLogging {
////////////////////////////////////////////////////////////////////////////////
-inline bool TLogger::IsAnchorUpToDate(const TLoggingAnchor& position) const
+inline bool TLogger::IsAnchorUpToDate(const TLoggingAnchor& anchor) const
{
return
!Category_ ||
- position.CurrentVersion == Category_->ActualVersion->load(std::memory_order::relaxed);
+ anchor.CurrentVersion == Category_->ActualVersion->load(std::memory_order::relaxed);
}
template <class... TArgs>
@@ -49,6 +49,17 @@ TLogger TLogger::WithStructuredTag(TStringBuf key, TType value) const
return result;
}
+Y_FORCE_INLINE ELogLevel TLogger::GetEffectiveLoggingLevel(ELogLevel level, const TLoggingAnchor& anchor)
+{
+ // Check if anchor is suppressed.
+ if (anchor.Suppressed.load(std::memory_order::relaxed)) {
+ return ELogLevel::Minimum;
+ }
+
+ // Compute the actual level taking anchor override into account.
+ return anchor.LevelOverride.load(std::memory_order::relaxed).value_or(level);
+}
+
Y_FORCE_INLINE bool TLogger::IsLevelEnabled(ELogLevel level) const
{
// This is the first check which is intended to be inlined next to
diff --git a/library/cpp/yt/logging/logger.h b/library/cpp/yt/logging/logger.h
index 4f0ed44ab7..35aba4eb4c 100644
--- a/library/cpp/yt/logging/logger.h
+++ b/library/cpp/yt/logging/logger.h
@@ -47,12 +47,17 @@ struct TLoggingCategory
struct TLoggingAnchor
{
std::atomic<bool> Registered = false;
+ TLoggingAnchor* NextAnchor = nullptr;
+
::TSourceLocation SourceLocation = {TStringBuf{}, 0};
TString AnchorMessage;
- TLoggingAnchor* NextAnchor = nullptr;
std::atomic<int> CurrentVersion = 0;
- std::atomic<bool> Enabled = false;
+
+ std::atomic<bool> Suppressed = false;
+
+ std::atomic<std::optional<ELogLevel>> LevelOverride;
+ static_assert(decltype(LevelOverride)::is_always_lock_free);
struct TCounter
{
@@ -189,6 +194,9 @@ public:
const TLoggingCategory* GetCategory() const;
+ //! Combines given #level and the override from #anchor.
+ static ELogLevel GetEffectiveLoggingLevel(ELogLevel level, const TLoggingAnchor& anchor);
+
//! Validate that level is admitted by logger's own min level
//! and by category's min level.
bool IsLevelEnabled(ELogLevel level) const;
@@ -300,40 +308,38 @@ void LogStructuredEvent(
do { \
const auto& logger__ = (logger)(); \
auto level__ = (level); \
- \
- if (!logger__.IsLevelEnabled(level__)) { \
- break; \
- } \
- \
auto location__ = __LOCATION__; \
\
::NYT::NLogging::TLoggingAnchor* anchor__ = (anchor); \
- if (!anchor__) { \
+ [[unlikely]] if (!anchor__) { \
static ::NYT::TLeakyStorage<::NYT::NLogging::TLoggingAnchor> staticAnchor__; \
anchor__ = staticAnchor__.Get(); \
} \
\
bool anchorUpToDate__ = logger__.IsAnchorUpToDate(*anchor__); \
- if (anchorUpToDate__ && !anchor__->Enabled.load(std::memory_order::relaxed)) { \
- break; \
+ [[likely]] if (anchorUpToDate__) { \
+ auto effectiveLevel__ = ::NYT::NLogging::TLogger::GetEffectiveLoggingLevel(level__, *anchor__); \
+ if (!logger__.IsLevelEnabled(effectiveLevel__)) { \
+ break; \
+ } \
} \
\
auto loggingContext__ = ::NYT::NLogging::GetLoggingContext(); \
auto message__ = ::NYT::NLogging::NDetail::BuildLogMessage(loggingContext__, logger__, __VA_ARGS__); \
\
- if (!anchorUpToDate__) { \
+ [[unlikely]] if (!anchorUpToDate__) { \
logger__.RegisterStaticAnchor(anchor__, location__, message__.Anchor); \
- logger__.UpdateAnchor(anchor__); \
} \
\
- if (!anchor__->Enabled.load(std::memory_order::relaxed)) { \
+ auto effectiveLevel__ = ::NYT::NLogging::TLogger::GetEffectiveLoggingLevel(level__, *anchor__); \
+ if (!logger__.IsLevelEnabled(effectiveLevel__)) { \
break; \
} \
\
::NYT::NLogging::NDetail::LogEventImpl( \
loggingContext__, \
logger__, \
- level__, \
+ effectiveLevel__, \
location__, \
anchor__, \
std::move(message__.MessageRef)); \
diff --git a/yt/cpp/mapreduce/interface/logging/yt_log.cpp b/yt/cpp/mapreduce/interface/logging/yt_log.cpp
index 6b1e8ff049..4ff38d4c58 100644
--- a/yt/cpp/mapreduce/interface/logging/yt_log.cpp
+++ b/yt/cpp/mapreduce/interface/logging/yt_log.cpp
@@ -30,8 +30,6 @@ public:
return;
}
- anchor->Enabled.store(true);
-
auto guard = Guard(Mutex_);
anchor->SourceLocation = sourceLocation;
anchor->AnchorMessage = anchorMessage;
diff --git a/yt/yt/core/logging/config.cpp b/yt/yt/core/logging/config.cpp
index 4acde166a9..4fc2823945 100644
--- a/yt/yt/core/logging/config.cpp
+++ b/yt/yt/core/logging/config.cpp
@@ -196,13 +196,16 @@ void TLogManagerConfig::Register(TRegistrar registrar)
registrar.Parameter("shutdown_busy_timeout", &TThis::ShutdownGraceTimeout)
.Default(TDuration::Zero());
- registrar.Parameter("writers", &TThis::Writers);
registrar.Parameter("rules", &TThis::Rules);
- registrar.Parameter("suppressed_messages", &TThis::SuppressedMessages)
- .Default();
+ registrar.Parameter("writers", &TThis::Writers);
registrar.Parameter("category_rate_limits", &TThis::CategoryRateLimits)
.Default();
+ registrar.Parameter("suppressed_messages", &TThis::SuppressedMessages)
+ .Optional();
+ registrar.Parameter("message_level_overrides", &TThis::MessageLevelOverrides)
+ .Optional();
+
registrar.Parameter("request_suppression_timeout", &TThis::RequestSuppressionTimeout)
.Alias("trace_suppression_timeout")
.Default(TDuration::Zero());
@@ -235,8 +238,12 @@ TLogManagerConfigPtr TLogManagerConfig::ApplyDynamic(const TLogManagerDynamicCon
mergedConfig->ShutdownGraceTimeout = ShutdownGraceTimeout;
mergedConfig->Rules = CloneYsonStructs(dynamicConfig->Rules.value_or(Rules));
mergedConfig->Writers = CloneYsonStructs(Writers);
- mergedConfig->SuppressedMessages = dynamicConfig->SuppressedMessages.value_or(SuppressedMessages);
mergedConfig->CategoryRateLimits = dynamicConfig->CategoryRateLimits.value_or(CategoryRateLimits);
+ mergedConfig->SuppressedMessages = dynamicConfig->SuppressedMessages.value_or(SuppressedMessages);
+ mergedConfig->MessageLevelOverrides = MessageLevelOverrides;
+ for (const auto& [message, level] : dynamicConfig->MessageLevelOverrides) {
+ mergedConfig->MessageLevelOverrides[message] = level;
+ }
mergedConfig->RequestSuppressionTimeout = dynamicConfig->RequestSuppressionTimeout.value_or(RequestSuppressionTimeout);
mergedConfig->EnableAnchorProfiling = dynamicConfig->EnableAnchorProfiling.value_or(EnableAnchorProfiling);
mergedConfig->MinLoggedMessageRateToProfile = dynamicConfig->MinLoggedMessageRateToProfile.value_or(MinLoggedMessageRateToProfile);
@@ -459,9 +466,12 @@ void TLogManagerDynamicConfig::Register(TRegistrar registrar)
registrar.Parameter("rules", &TThis::Rules)
.Optional();
+ registrar.Parameter("category_rate_limits", &TThis::CategoryRateLimits)
+ .Optional();
+
registrar.Parameter("suppressed_messages", &TThis::SuppressedMessages)
.Optional();
- registrar.Parameter("category_rate_limits", &TThis::CategoryRateLimits)
+ registrar.Parameter("message_level_overrides", &TThis::MessageLevelOverrides)
.Optional();
registrar.Parameter("request_suppression_timeout", &TThis::RequestSuppressionTimeout)
diff --git a/yt/yt/core/logging/config.h b/yt/yt/core/logging/config.h
index 6e5f2b0f9f..f025e58f11 100644
--- a/yt/yt/core/logging/config.h
+++ b/yt/yt/core/logging/config.h
@@ -160,9 +160,13 @@ public:
std::vector<TRuleConfigPtr> Rules;
THashMap<TString, NYTree::IMapNodePtr> Writers;
- std::vector<TString> SuppressedMessages;
THashMap<TString, i64> CategoryRateLimits;
+ //! Messages with these prefixes will not be logged regardless of the configured levels.
+ std::vector<TString> SuppressedMessages;
+ //! Overrides levels of messages with a matching prefix .
+ THashMap<TString, ELogLevel> MessageLevelOverrides;
+
TDuration RequestSuppressionTimeout;
bool EnableAnchorProfiling;
@@ -215,9 +219,11 @@ public:
std::optional<int> LowBacklogWatermark;
std::optional<std::vector<TRuleConfigPtr>> Rules;
- std::optional<std::vector<TString>> SuppressedMessages;
std::optional<THashMap<TString, i64>> CategoryRateLimits;
+ std::optional<std::vector<TString>> SuppressedMessages;
+ THashMap<TString, ELogLevel> MessageLevelOverrides;
+
std::optional<TDuration> RequestSuppressionTimeout;
std::optional<bool> EnableAnchorProfiling;
diff --git a/yt/yt/core/logging/log_manager.cpp b/yt/yt/core/logging/log_manager.cpp
index 1a6d51cb02..d7e15992be 100644
--- a/yt/yt/core/logging/log_manager.cpp
+++ b/yt/yt/core/logging/log_manager.cpp
@@ -511,29 +511,24 @@ public:
{
auto guard = Guard(SpinLock_);
auto config = Config_.Acquire();
-
- bool enabled = true;
- for (const auto& prefix : config->SuppressedMessages) {
- if (anchor->AnchorMessage.StartsWith(prefix)) {
- enabled = false;
- break;
- }
- }
-
- anchor->Enabled.store(enabled, std::memory_order::relaxed);
- anchor->CurrentVersion.store(GetVersion(), std::memory_order::relaxed);
+ DoUpdateAnchor(config, anchor);
}
- void RegisterStaticAnchor(TLoggingAnchor* anchor, ::TSourceLocation sourceLocation, TStringBuf message)
+ void RegisterStaticAnchor(
+ TLoggingAnchor* anchor,
+ ::TSourceLocation sourceLocation,
+ TStringBuf message)
{
if (anchor->Registered.exchange(true)) {
return;
}
auto guard = Guard(SpinLock_);
+ auto config = Config_.Acquire();
anchor->SourceLocation = sourceLocation;
anchor->AnchorMessage = BuildAnchorMessage(sourceLocation, message);
DoRegisterAnchor(anchor);
+ DoUpdateAnchor(config, anchor);
}
TLoggingAnchor* RegisterDynamicAnchor(TString anchorMessage)
@@ -1356,9 +1351,7 @@ private:
return eventsWritten;
}
- void DoUpdateCategory(
- const TLogManagerConfigPtr& config,
- TLoggingCategory* category)
+ void DoUpdateCategory(const TLogManagerConfigPtr& config, TLoggingCategory* category)
{
VERIFY_THREAD_AFFINITY_ANY();
@@ -1384,6 +1377,33 @@ private:
FirstAnchor_.store(anchor);
}
+ void DoUpdateAnchor(const TLogManagerConfigPtr& config, TLoggingAnchor* anchor)
+ {
+ VERIFY_SPINLOCK_AFFINITY(SpinLock_);
+
+ auto isPrefixOf = [] (const TString& message, const std::vector<TString>& prefixes) {
+ for (const auto& prefix : prefixes) {
+ if (message.StartsWith(prefix)) {
+ return true;
+ }
+ }
+ return false;
+ };
+
+ auto findByPrefix = [] (const TString& message, const THashMap<TString, ELogLevel>& levelOverrides) -> std::optional<ELogLevel> {
+ for (const auto& [prefix, level] : levelOverrides) {
+ if (message.StartsWith(prefix)) {
+ return level;
+ }
+ }
+ return std::nullopt;
+ };
+
+ anchor->Suppressed.store(isPrefixOf(anchor->AnchorMessage, config->SuppressedMessages));
+ anchor->LevelOverride.store(findByPrefix(anchor->AnchorMessage, config->MessageLevelOverrides));
+ anchor->CurrentVersion.store(GetVersion());
+ }
+
static TString BuildAnchorMessage(::TSourceLocation sourceLocation, TStringBuf message)
{
if (message) {
diff --git a/yt/yt/core/logging/unittests/logging_ut.cpp b/yt/yt/core/logging/unittests/logging_ut.cpp
index c967675ae1..1abc7fe271 100644
--- a/yt/yt/core/logging/unittests/logging_ut.cpp
+++ b/yt/yt/core/logging/unittests/logging_ut.cpp
@@ -224,14 +224,14 @@ TEST_F(TLoggingTest, ReloadOnSighup)
Configure(Format(R"({
rules = [
{
- "min_level" = "info";
- "writers" = [ "info" ];
+ min_level = info;
+ writers = [ info ];
};
];
- "writers" = {
- "info" = {
- "file_name" = "%v";
- "type" = "file";
+ writers = {
+ info = {
+ file_name = "%v";
+ type = "file";
};
};
})", logFile.Name()));
@@ -272,14 +272,14 @@ TEST_F(TLoggingTest, ReloadOnRename)
watch_period = 1000;
rules = [
{
- "min_level" = "info";
- "writers" = [ "info" ];
+ min_level = info;
+ writers = [ info ];
};
];
- "writers" = {
- "info" = {
- "file_name" = "%v";
- "type" = "file";
+ writers = {
+ info = {
+ file_name = "%v";
+ type = "file";
};
};
})", logFile.Name()));
@@ -442,22 +442,22 @@ TEST_F(TLoggingTest, LogManager)
Configure(Format(R"({
rules = [
{
- "min_level" = "info";
- "writers" = [ "info" ];
+ min_level = info;
+ writers = [ info ];
};
{
- "min_level" = "error";
- "writers" = [ "error" ];
+ min_level = "error";
+ writers = [ "error" ];
};
];
- "writers" = {
+ writers = {
"error" = {
- "file_name" = "%v";
- "type" = "file";
+ file_name = "%v";
+ type = "file";
};
- "info" = {
- "file_name" = "%v";
- "type" = "file";
+ info = {
+ file_name = "%v";
+ type = "file";
};
};
})", errorFile.Name(), infoFile.Name()));
@@ -486,14 +486,14 @@ TEST_F(TLoggingTest, ThreadMinLogLevel)
Configure(Format(R"({
rules = [
{
- "min_level" = "debug";
- "writers" = [ "debug" ];
+ min_level = "debug";
+ writers = [ "debug" ];
};
];
- "writers" = {
+ writers = {
"debug" = {
- "file_name" = "%v";
- "type" = "file";
+ file_name = "%v";
+ type = "file";
};
};
})", debugFile.Name()));
@@ -702,15 +702,15 @@ TEST_F(TLoggingTest, StructuredLoggingWithValidator)
rules = [
{
"family" = "structured";
- "min_level" = "info";
- "writers" = [ "test" ];
+ min_level = info;
+ writers = [ "test" ];
};
];
- "writers" = {
+ writers = {
"test" = {
"format" = "structured";
- "file_name" = "%v";
- "type" = "file";
+ file_name = "%v";
+ type = "file";
};
};
"structured_validation_sampling_rate" = 1.0;
@@ -752,15 +752,15 @@ TEST_F(TLoggingTest, StructuredValidationWithSamplingRate)
rules = [
{
"family" = "structured";
- "min_level" = "info";
- "writers" = [ "test" ];
+ min_level = info;
+ writers = [ "test" ];
};
];
- "writers" = {
+ writers = {
"test" = {
- "file_name" = "%v";
+ file_name = "%v";
"format" = "structured";
- "type" = "file";
+ type = "file";
}
};
"structured_validation_sampling_rate" = 0.5;
@@ -842,15 +842,15 @@ TEST_P(TBuiltinRotationTest, All)
flush_period = 100;
rules = [
{
- "min_level" = "info";
- "writers" = [ "info" ];
+ min_level = info;
+ writers = [ info ];
};
];
- "writers" = {
- "info" = {
- "file_name" = "%v";
+ writers = {
+ info = {
+ file_name = "%v";
"use_timestamp_suffix" = %v;
- "type" = "file";
+ type = "file";
"rotation_policy" = {
"max_segment_count_to_keep" = %v;
"max_segment_size" = 10;
@@ -1062,14 +1062,14 @@ TEST_F(TLoggingTest, DISABLED_LogFatal)
Configure(Format(R"({
rules = [
{
- "min_level" = "info";
- "writers" = [ "info" ];
+ min_level = info;
+ writers = [ info ];
};
];
- "writers" = {
- "info" = {
- "file_name" = "%v";
- "type" = "file";
+ writers = {
+ info = {
+ file_name = "%v";
+ type = "file";
};
};
})", logFile.Name()));
@@ -1084,21 +1084,21 @@ TEST_F(TLoggingTest, DISABLED_LogFatal)
// Windows does not support request tracing for now.
#ifndef _win_
-TEST_F(TLoggingTest, RequestSuppression)
+TEST_F(TLoggingTest, SupressedRequests)
{
TTempFile logFile(GenerateLogFileName());
Configure(Format(R"({
rules = [
{
- "min_level" = "info";
- "writers" = [ "info" ];
+ min_level = info;
+ writers = [ info ];
};
];
- "writers" = {
- "info" = {
- "file_name" = "%v";
- "type" = "file";
+ writers = {
+ info = {
+ file_name = "%v";
+ type = "file";
};
};
"request_suppression_timeout" = 100;
@@ -1125,6 +1125,73 @@ TEST_F(TLoggingTest, RequestSuppression)
}
#endif
+TEST_F(TLoggingTest, SuppressedMessages)
+{
+ TTempFile logFile(GenerateLogFileName());
+
+ Configure(Format(R"({
+ rules = [
+ {
+ min_level = info;
+ writers = [ info ];
+ };
+ ];
+ writers = {
+ info = {
+ file_name = "%v";
+ type = "file";
+ };
+ };
+ suppressed_messages = ["Suppressed message"];
+ })", logFile.Name()));
+
+ YT_LOG_INFO("Suppressed message 1");
+ YT_LOG_INFO("Suppressed message 2");
+ YT_LOG_INFO("Good message");
+
+ TLogManager::Get()->Synchronize();
+
+ auto lines = ReadPlainTextEvents(logFile.Name());
+ EXPECT_EQ(1, std::ssize(lines));
+ EXPECT_TRUE(lines[0].find("Good message") != TString::npos);
+}
+
+TEST_F(TLoggingTest, MessageLevelOverride)
+{
+ TTempFile logFile(GenerateLogFileName());
+
+ Configure(Format(R"({
+ rules = [
+ {
+ min_level = info;
+ writers = [ info ];
+ };
+ ];
+ writers = {
+ info = {
+ file_name = "%v";
+ type = "file";
+ };
+ };
+ message_level_overrides = {
+ "Overridden message" = "info";
+ };
+ })", logFile.Name()));
+
+ YT_LOG_INFO("Overridden message 1");
+ YT_LOG_TRACE("Overridden message 2");
+ YT_LOG_INFO("Good message");
+
+ TLogManager::Get()->Synchronize();
+
+ auto lines = ReadPlainTextEvents(logFile.Name());
+ for (auto l : lines) Cerr << l << Endl;
+ EXPECT_EQ(3, std::ssize(lines));
+ EXPECT_TRUE(lines[0].find("Overridden message 1") != TString::npos);
+ EXPECT_TRUE(lines[1].find("Overridden message 2") != TString::npos);
+ EXPECT_TRUE(lines[2].find("Good message") != TString::npos);
+}
+
////////////////////////////////////////////////////////////////////////////////
class TLoggingTagsTest
@@ -1198,15 +1265,15 @@ protected:
Configure(Format(R"({
rules = [
{
- "min_level" = "info";
- "max_level" = "info";
- "writers" = [ "info" ];
+ min_level = info;
+ "max_level" = info;
+ writers = [ info ];
};
];
- "writers" = {
- "info" = {
- "file_name" = "%v";
- "type" = "file";
+ writers = {
+ info = {
+ file_name = "%v";
+ type = "file";
};
};
})", fileName));
@@ -1388,9 +1455,9 @@ TEST_F(TCustomWriterTest, UnknownWriterType)
{
Configure(R"({
"rules" = [];
- "writers" = {
+ writers = {
"custom" = {
- "type" = "unknown";
+ type = "unknown";
};
};
})");
@@ -1404,9 +1471,9 @@ TEST_F(TCustomWriterTest, WriterConfigValidation)
{
Configure(Format(R"({
"rules" = [];
- "writers" = {
+ writers = {
"custom" = {
- "type" = "%v";
+ type = "%v";
"padding" = -10;
};
};
@@ -1420,13 +1487,13 @@ TEST_F(TCustomWriterTest, Write)
Configure(Format(R"({
"rules" = [
{
- "min_level" = "info";
- "writers" = [ "custom" ];
+ min_level = info;
+ writers = [ "custom" ];
}
];
- "writers" = {
+ writers = {
"custom" = {
- "type" = "%v";
+ type = "%v";
"padding" = 2;
};
};