From 955f537bd5ef2f4a29717ac4999ce2af47b4c039 Mon Sep 17 00:00:00 2001 From: Pablo Marcos Date: Fri, 8 Nov 2024 12:28:06 +0000 Subject: [PATCH] Add a new setting query_metric_log_debug to avoid the noise --- src/Core/Settings.cpp | 5 +++++ src/Core/SettingsChangesHistory.cpp | 1 + src/Interpreters/QueryMetricLog.cpp | 18 +++++++++++------- src/Interpreters/QueryMetricLog.h | 3 ++- src/Interpreters/executeQuery.cpp | 3 ++- .../03203_system_query_metric_log.sh | 10 +++++----- 6 files changed, 26 insertions(+), 14 deletions(-) diff --git a/src/Core/Settings.cpp b/src/Core/Settings.cpp index 081e07ca2ce..d07cd7352a1 100644 --- a/src/Core/Settings.cpp +++ b/src/Core/Settings.cpp @@ -2784,6 +2784,11 @@ If set to any negative value, it will take the value `collect_interval_milliseco To disable the collection of a single query, set `query_metric_log_interval` to 0. Default value: -1 + )", 0) \ + DECLARE(Bool, query_metric_log_debug, false, R"( +Turns on debugging traces for system.query_metric_log + +Default value: false )", 0) \ DECLARE(LogsLevel, send_logs_level, LogsLevel::fatal, R"( Send server text logs with specified minimum level to client. Valid values: 'trace', 'debug', 'information', 'warning', 'error', 'fatal', 'none' diff --git a/src/Core/SettingsChangesHistory.cpp b/src/Core/SettingsChangesHistory.cpp index ed87fde8b7e..a3e21aa670f 100644 --- a/src/Core/SettingsChangesHistory.cpp +++ b/src/Core/SettingsChangesHistory.cpp @@ -75,6 +75,7 @@ static std::initializer_listgetProcessList(); @@ -222,21 +223,24 @@ void QueryMetricLogStatus::scheduleNext(String query_id) } else { - LOG_TRACE(logger, "The next collecting task for query {} should have already run at {}. Scheduling it right now", - query_id, timePointToString(next_collect_time)); + if (debug_traces) + LOG_DEBUG(logger, "The next collecting task for query {} should have already run at {}. Scheduling it right now", + query_id, timePointToString(next_collect_time)); task->schedule(); } } std::optional QueryMetricLogStatus::createLogMetricElement(const String & query_id, const QueryStatusInfo & query_info, TimePoint query_info_time, bool schedule_next) { - LOG_TRACE(logger, "Collecting query_metric_log for query {} and interval {} ms with QueryStatusInfo from {}. Next collection time: {}", - query_id, interval_milliseconds, timePointToString(query_info_time), - schedule_next ? timePointToString(next_collect_time + std::chrono::milliseconds(interval_milliseconds)) : "finished"); + if (debug_traces) + LOG_DEBUG(logger, "Collecting query_metric_log for query {} and interval {} ms with QueryStatusInfo from {}. Next collection time: {}", + query_id, interval_milliseconds, timePointToString(query_info_time), + schedule_next ? timePointToString(next_collect_time + std::chrono::milliseconds(interval_milliseconds)) : "finished"); if (query_info_time <= last_collect_time) { - LOG_TRACE(logger, "Query {} has a more recent metrics collected. Skipping this one", query_id); + if (debug_traces) + LOG_DEBUG(logger, "Query {} has a more recent metrics collected. Skipping this one", query_id); return {}; } diff --git a/src/Interpreters/QueryMetricLog.h b/src/Interpreters/QueryMetricLog.h index 65764229b0a..5f301b2cd13 100644 --- a/src/Interpreters/QueryMetricLog.h +++ b/src/Interpreters/QueryMetricLog.h @@ -51,6 +51,7 @@ struct QueryMetricLogStatus std::chrono::system_clock::time_point next_collect_time TSA_GUARDED_BY(getMutex()); std::vector last_profile_events TSA_GUARDED_BY(getMutex()) = std::vector(ProfileEvents::end()); BackgroundSchedulePool::TaskHolder task TSA_GUARDED_BY(getMutex()); + bool debug_traces = false; /// We need to be able to move it for the hash map, so we need to add an indirection here. std::unique_ptr mutex = std::make_unique(); @@ -78,7 +79,7 @@ public: void shutdown() final; /// Both startQuery and finishQuery are called from the thread that executes the query. - void startQuery(const String & query_id, TimePoint start_time, UInt64 interval_milliseconds); + void startQuery(const String & query_id, TimePoint start_time, UInt64 interval_milliseconds, bool debug_traces = false); void finishQuery(const String & query_id, TimePoint finish_time, QueryStatusInfoPtr query_info = nullptr); private: diff --git a/src/Interpreters/executeQuery.cpp b/src/Interpreters/executeQuery.cpp index 4507126b7b3..794d3dab0e6 100644 --- a/src/Interpreters/executeQuery.cpp +++ b/src/Interpreters/executeQuery.cpp @@ -146,6 +146,7 @@ namespace Setting extern const SettingsQueryCacheSystemTableHandling query_cache_system_table_handling; extern const SettingsSeconds query_cache_ttl; extern const SettingsInt64 query_metric_log_interval; + extern const SettingsBool query_metric_log_debug; extern const SettingsOverflowMode read_overflow_mode; extern const SettingsOverflowMode read_overflow_mode_leaf; extern const SettingsOverflowMode result_overflow_mode; @@ -455,7 +456,7 @@ QueryLogElement logQueryStart( { auto interval_milliseconds = getQueryMetricLogInterval(context); if (interval_milliseconds > 0) - query_metric_log->startQuery(elem.client_info.current_query_id, query_start_time, interval_milliseconds); + query_metric_log->startQuery(elem.client_info.current_query_id, query_start_time, interval_milliseconds, settings[Setting::query_metric_log_debug]); } return elem; diff --git a/tests/queries/0_stateless/03203_system_query_metric_log.sh b/tests/queries/0_stateless/03203_system_query_metric_log.sh index abcd14c8e5d..4bc764b777c 100755 --- a/tests/queries/0_stateless/03203_system_query_metric_log.sh +++ b/tests/queries/0_stateless/03203_system_query_metric_log.sh @@ -6,11 +6,11 @@ CURDIR=$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd) readonly query_prefix=$CLICKHOUSE_DATABASE -$CLICKHOUSE_CLIENT --query-id="${query_prefix}_1000" -q "SELECT sleep(2.5) FORMAT Null" & -$CLICKHOUSE_CLIENT --query-id="${query_prefix}_400" -q "SELECT sleep(2.5) SETTINGS query_metric_log_interval=400 FORMAT Null" & -$CLICKHOUSE_CLIENT --query-id="${query_prefix}_123" -q "SELECT sleep(2.5) SETTINGS query_metric_log_interval=123 FORMAT Null" & -$CLICKHOUSE_CLIENT --query-id="${query_prefix}_0" -q "SELECT sleep(2.5) SETTINGS query_metric_log_interval=0 FORMAT Null" & -$CLICKHOUSE_CLIENT --query-id="${query_prefix}_fast" -q "SELECT sleep(0.1) FORMAT Null" & +$CLICKHOUSE_CLIENT --query-id="${query_prefix}_1000" -q "SELECT sleep(2.5) SETTINGS query_metric_log_debug=true FORMAT Null" & +$CLICKHOUSE_CLIENT --query-id="${query_prefix}_400" -q "SELECT sleep(2.5) SETTINGS query_metric_log_debug=true, query_metric_log_interval=400 FORMAT Null" & +$CLICKHOUSE_CLIENT --query-id="${query_prefix}_123" -q "SELECT sleep(2.5) SETTINGS query_metric_log_debug=true, query_metric_log_interval=123 FORMAT Null" & +$CLICKHOUSE_CLIENT --query-id="${query_prefix}_0" -q "SELECT sleep(2.5) SETTINGS query_metric_log_debug=true, query_metric_log_interval=0 FORMAT Null" & +$CLICKHOUSE_CLIENT --query-id="${query_prefix}_fast" -q "SELECT sleep(0.1) SETTINGS query_metric_log_debug=true FORMAT Null" & wait