From 2754895c117dea76a65eae5c7c5ab4f918f21eba Mon Sep 17 00:00:00 2001 From: "Alexander A. Klimov" Date: Mon, 5 Sep 2022 15:28:36 +0200 Subject: [PATCH 1/4] Icinga DB: on every check result update state only 1x, not 3x in a row Before (time: vertical, stack: horizontal): * Checkable::ExecuteCheck * Checkable::UpdateNextCheck * IcingaDB::NextCheckChangedHandler * HSET icinga:host:state * HSET icinga:checksum:host:state * ZADD icinga:nextupdate:host * RandomCheckTask::ScriptFunc * Checkable::ProcessCheckResult * Checkable::UpdateNextCheck * IcingaDB::NextCheckChangedHandler * HSET icinga:host:state * HSET icinga:checksum:host:state * ZADD icinga:nextupdate:host * IcingaDB::NewCheckResultHandler * HSET icinga:host:state * HSET icinga:checksum:host:state * ZADD icinga:nextupdate:host * IcingaDB::StateChangeHandler * XADD icinga:runtime:state * IcingaDB::ForwardHistoryEntries * XADD icinga:history:stream:state After: * Checkable::ExecuteCheck * Checkable::UpdateNextCheck * RandomCheckTask::ScriptFunc * Checkable::ProcessCheckResult * Checkable::UpdateNextCheck * IcingaDB::NewCheckResultHandler * HSET icinga:host:state * HSET icinga:checksum:host:state * ZADD icinga:nextupdate:host * IcingaDB::StateChangeHandler * XADD icinga:runtime:state * IcingaDB::ForwardHistoryEntries * XADD icinga:history:stream:state The first state + nextupdate (for overdue) update comes from next_check being set to now + interval immediately before doing the actual check (not to trigger it twice). This update is not only not important for the end user, but even inappropriate. The end user SHALL see next_check being e.g. in -4s, not 5m, as the check is running at the moment. The second one is just redundant as IcingaDB::NewCheckResultHandler (the third one) is called anyway and will update state + nextupdate as well. --- lib/icingadb/icingadb-objects.cpp | 6 +++--- lib/icingadb/icingadb.hpp | 2 +- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/lib/icingadb/icingadb-objects.cpp b/lib/icingadb/icingadb-objects.cpp index f9533b483..ac1469ba5 100644 --- a/lib/icingadb/icingadb-objects.cpp +++ b/lib/icingadb/icingadb-objects.cpp @@ -126,8 +126,8 @@ void IcingaDB::ConfigStaticInitialize() IcingaDB::NewCheckResultHandler(checkable); }); - Checkable::OnNextCheckChanged.connect([](const Checkable::Ptr& checkable, const Value&) { - IcingaDB::NextCheckChangedHandler(checkable); + Checkable::OnNextCheckUpdated.connect([](const Checkable::Ptr& checkable) { + IcingaDB::NextCheckUpdatedHandler(checkable); }); Service::OnHostProblemChanged.connect([](const Service::Ptr& service, const CheckResult::Ptr&, const MessageOrigin::Ptr&) { @@ -2805,7 +2805,7 @@ void IcingaDB::NewCheckResultHandler(const Checkable::Ptr& checkable) } } -void IcingaDB::NextCheckChangedHandler(const Checkable::Ptr& checkable) +void IcingaDB::NextCheckUpdatedHandler(const Checkable::Ptr& checkable) { for (auto& rw : ConfigType::GetObjectsByType()) { rw->UpdateState(checkable, StateUpdate::Volatile); diff --git a/lib/icingadb/icingadb.hpp b/lib/icingadb/icingadb.hpp index 21311453e..6652d9c1f 100644 --- a/lib/icingadb/icingadb.hpp +++ b/lib/icingadb/icingadb.hpp @@ -179,7 +179,7 @@ private: static void CommentRemovedHandler(const Comment::Ptr& comment); static void FlappingChangeHandler(const Checkable::Ptr& checkable, double changeTime); static void NewCheckResultHandler(const Checkable::Ptr& checkable); - static void NextCheckChangedHandler(const Checkable::Ptr& checkable); + static void NextCheckUpdatedHandler(const Checkable::Ptr& checkable); static void HostProblemChangedHandler(const Service::Ptr& service); static void AcknowledgementSetHandler(const Checkable::Ptr& checkable, const String& author, const String& comment, AcknowledgementType type, bool persistent, double changeTime, double expiry); static void AcknowledgementClearedHandler(const Checkable::Ptr& checkable, const String& removedBy, double changeTime); From 865c5b83659daba9ce155fc51476142e7dac3ddb Mon Sep 17 00:00:00 2001 From: "Alexander A. Klimov" Date: Wed, 7 Sep 2022 15:44:12 +0200 Subject: [PATCH 2/4] Utility::ValidateUTF8(): move a string instead of copying a vector less malloc() = more speed Especially as JsonEncode() validates every single input string. --- lib/base/utility.cpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/base/utility.cpp b/lib/base/utility.cpp index a52121366..a2930a0f8 100644 --- a/lib/base/utility.cpp +++ b/lib/base/utility.cpp @@ -1779,8 +1779,8 @@ const char l_Utf8Replacement[] = "\xEF\xBF\xBD"; String Utility::ValidateUTF8(const String& input) { - std::vector output; - output.reserve(input.GetLength() * 3u); + std::string output; + output.reserve(input.GetLength()); try { utf8::replace_invalid(input.Begin(), input.End(), std::back_inserter(output)); @@ -1788,7 +1788,7 @@ String Utility::ValidateUTF8(const String& input) output.insert(output.end(), (const char*)l_Utf8Replacement, (const char*)l_Utf8Replacement + 3); } - return String(output.begin(), output.end()); + return String(std::move(output)); } String Utility::CreateTempFile(const String& path, int mode, std::fstream& fp) From de60eb445baf495fdecc90df7a2d9f003229b5a4 Mon Sep 17 00:00:00 2001 From: "Alexander A. Klimov" Date: Thu, 8 Sep 2022 12:09:25 +0200 Subject: [PATCH 3/4] Logger: don't render log messages which will be disposed anyway by caching the total minimum log severity of all loggers in a "global variable" and whether a message's severity is large enough for any of the loggers in a per-message no-op flag. --- lib/base/logger.cpp | 71 ++++++++++++++++++++++++++++++++++++++++----- lib/base/logger.hpp | 18 +++++++++++- lib/base/logger.ti | 2 +- 3 files changed, 82 insertions(+), 9 deletions(-) diff --git a/lib/base/logger.cpp b/lib/base/logger.cpp index 531839ca3..0be7279b2 100644 --- a/lib/base/logger.cpp +++ b/lib/base/logger.cpp @@ -12,6 +12,7 @@ #ifdef _WIN32 #include "base/windowseventloglogger.hpp" #endif /* _WIN32 */ +#include #include #include @@ -35,6 +36,8 @@ bool Logger::m_ConsoleLogEnabled = true; std::atomic Logger::m_EarlyLoggingEnabled (true); bool Logger::m_TimestampEnabled = true; LogSeverity Logger::m_ConsoleLogSeverity = LogInformation; +std::mutex Logger::m_UpdateMinLogSeverityMutex; +Atomic Logger::m_MinLogSeverity (LogDebug); INITIALIZE_ONCE([]() { ScriptGlobal::Set("System.LogDebug", LogDebug, true); @@ -51,8 +54,12 @@ void Logger::Start(bool runtimeCreated) { ObjectImpl::Start(runtimeCreated); - std::unique_lock lock(m_Mutex); - m_Loggers.insert(this); + { + std::unique_lock lock(m_Mutex); + m_Loggers.insert(this); + } + + UpdateMinLogSeverity(); } void Logger::Stop(bool runtimeRemoved) @@ -62,6 +69,8 @@ void Logger::Stop(bool runtimeRemoved) m_Loggers.erase(this); } + UpdateMinLogSeverity(); + ObjectImpl::Stop(runtimeRemoved); } @@ -139,11 +148,15 @@ LogSeverity Logger::StringToSeverity(const String& severity) void Logger::DisableConsoleLog() { m_ConsoleLogEnabled = false; + + UpdateMinLogSeverity(); } void Logger::EnableConsoleLog() { m_ConsoleLogEnabled = true; + + UpdateMinLogSeverity(); } bool Logger::IsConsoleLogEnabled() @@ -163,6 +176,8 @@ LogSeverity Logger::GetConsoleLogSeverity() void Logger::DisableEarlyLogging() { m_EarlyLoggingEnabled = false; + + UpdateMinLogSeverity(); } bool Logger::IsEarlyLoggingEnabled() { @@ -184,6 +199,13 @@ bool Logger::IsTimestampEnabled() return m_TimestampEnabled; } +void Logger::SetSeverity(const String& value, bool suppress_events, const Value& cookie) +{ + ObjectImpl::SetSeverity(value, suppress_events, cookie); + + UpdateMinLogSeverity(); +} + void Logger::ValidateSeverity(const Lazy& lvalue, const ValidationUtils& utils) { ObjectImpl::ValidateSeverity(lvalue, utils); @@ -195,14 +217,42 @@ void Logger::ValidateSeverity(const Lazy& lvalue, const ValidationUtils& } } -Log::Log(LogSeverity severity, String facility, const String& message) - : m_Severity(severity), m_Facility(std::move(facility)) +void Logger::UpdateMinLogSeverity() { - m_Buffer << message; + std::unique_lock lock (m_UpdateMinLogSeverityMutex); + auto result (LogNothing); + + for (auto& logger : Logger::GetLoggers()) { + ObjectLock llock (logger); + + if (logger->IsActive()) { + result = std::min(result, logger->GetMinSeverity()); + } + } + + if (Logger::IsConsoleLogEnabled()) { + result = std::min(result, Logger::GetConsoleLogSeverity()); + } + +#ifdef _WIN32 + if (Logger::IsEarlyLoggingEnabled()) { + result = std::min(result, LogCritical); + } +#endif /* _WIN32 */ + + m_MinLogSeverity.store(result); +} + +Log::Log(LogSeverity severity, String facility, const String& message) + : Log(severity, std::move(facility)) +{ + if (!m_IsNoOp) { + m_Buffer << message; + } } Log::Log(LogSeverity severity, String facility) - : m_Severity(severity), m_Facility(std::move(facility)) + : m_Severity(severity), m_Facility(std::move(facility)), m_IsNoOp(severity < Logger::GetMinLogSeverity()) { } /** @@ -210,6 +260,10 @@ Log::Log(LogSeverity severity, String facility) */ Log::~Log() { + if (m_IsNoOp) { + return; + } + LogEntry entry; entry.Timestamp = Utility::GetTime(); entry.Severity = m_Severity; @@ -264,6 +318,9 @@ Log::~Log() Log& Log::operator<<(const char *val) { - m_Buffer << val; + if (!m_IsNoOp) { + m_Buffer << val; + } + return *this; } diff --git a/lib/base/logger.hpp b/lib/base/logger.hpp index 6d87c29b7..10e0872ae 100644 --- a/lib/base/logger.hpp +++ b/lib/base/logger.hpp @@ -3,6 +3,7 @@ #ifndef LOGGER_H #define LOGGER_H +#include "base/atomic.hpp" #include "base/i2-base.hpp" #include "base/logger-ti.hpp" #include @@ -22,7 +23,10 @@ enum LogSeverity LogNotice, LogInformation, LogWarning, - LogCritical + LogCritical, + + // Just for internal comparision + LogNothing, }; /** @@ -76,6 +80,13 @@ public: static void SetConsoleLogSeverity(LogSeverity logSeverity); static LogSeverity GetConsoleLogSeverity(); + static inline + LogSeverity GetMinLogSeverity() + { + return m_MinLogSeverity.load(); + } + + void SetSeverity(const String& value, bool suppress_events = false, const Value& cookie = Empty) override; void ValidateSeverity(const Lazy& lvalue, const ValidationUtils& utils) final; protected: @@ -83,12 +94,16 @@ protected: void Stop(bool runtimeRemoved) override; private: + static void UpdateMinLogSeverity(); + static std::mutex m_Mutex; static std::set m_Loggers; static bool m_ConsoleLogEnabled; static std::atomic m_EarlyLoggingEnabled; static bool m_TimestampEnabled; static LogSeverity m_ConsoleLogSeverity; + static std::mutex m_UpdateMinLogSeverityMutex; + static Atomic m_MinLogSeverity; }; class Log @@ -116,6 +131,7 @@ private: LogSeverity m_Severity; String m_Facility; std::ostringstream m_Buffer; + bool m_IsNoOp; }; extern template Log& Log::operator<<(const Value&); diff --git a/lib/base/logger.ti b/lib/base/logger.ti index b9776c83d..44226cee4 100644 --- a/lib/base/logger.ti +++ b/lib/base/logger.ti @@ -9,7 +9,7 @@ namespace icinga abstract class Logger : ConfigObject { - [config] String severity { + [config, virtual] String severity { default {{{ return "information"; }}} }; }; From a4de67d5584a857b9f5c233ba6cc573ed589c940 Mon Sep 17 00:00:00 2001 From: Yonas Habteab Date: Thu, 8 Sep 2022 16:31:47 +0200 Subject: [PATCH 4/4] RedisConnection: Don't log queries that are going to be discarded --- lib/icingadb/redisconnection.cpp | 20 ++++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) diff --git a/lib/icingadb/redisconnection.cpp b/lib/icingadb/redisconnection.cpp index d9233ca77..798a8279b 100644 --- a/lib/icingadb/redisconnection.cpp +++ b/lib/icingadb/redisconnection.cpp @@ -115,7 +115,7 @@ void LogQuery(RedisConnection::Query& query, Log& msg) */ void RedisConnection::FireAndForgetQuery(RedisConnection::Query query, RedisConnection::QueryPriority priority, QueryAffects affects) { - { + if (LogDebug >= Logger::GetMinLogSeverity()) { Log msg (LogDebug, "IcingaDB", "Firing and forgetting query:"); LogQuery(query, msg); } @@ -138,9 +138,11 @@ void RedisConnection::FireAndForgetQuery(RedisConnection::Query query, RedisConn */ void RedisConnection::FireAndForgetQueries(RedisConnection::Queries queries, RedisConnection::QueryPriority priority, QueryAffects affects) { - for (auto& query : queries) { - Log msg (LogDebug, "IcingaDB", "Firing and forgetting query:"); - LogQuery(query, msg); + if (LogDebug >= Logger::GetMinLogSeverity()) { + for (auto& query : queries) { + Log msg(LogDebug, "IcingaDB", "Firing and forgetting query:"); + LogQuery(query, msg); + } } auto item (Shared::Make(std::move(queries))); @@ -163,7 +165,7 @@ void RedisConnection::FireAndForgetQueries(RedisConnection::Queries queries, Red */ RedisConnection::Reply RedisConnection::GetResultOfQuery(RedisConnection::Query query, RedisConnection::QueryPriority priority, QueryAffects affects) { - { + if (LogDebug >= Logger::GetMinLogSeverity()) { Log msg (LogDebug, "IcingaDB", "Executing query:"); LogQuery(query, msg); } @@ -194,9 +196,11 @@ RedisConnection::Reply RedisConnection::GetResultOfQuery(RedisConnection::Query */ RedisConnection::Replies RedisConnection::GetResultsOfQueries(RedisConnection::Queries queries, RedisConnection::QueryPriority priority, QueryAffects affects) { - for (auto& query : queries) { - Log msg (LogDebug, "IcingaDB", "Executing query:"); - LogQuery(query, msg); + if (LogDebug >= Logger::GetMinLogSeverity()) { + for (auto& query : queries) { + Log msg(LogDebug, "IcingaDB", "Executing query:"); + LogQuery(query, msg); + } } std::promise promise;