From 365b5207b7d02384f4c3e28402c4b3d748f443df Mon Sep 17 00:00:00 2001 From: Azat Khuzhin Date: Sun, 5 Apr 2020 00:07:00 +0300 Subject: [PATCH] Add log_queries_min_type to filter which entries will be written to query_log Can be used to write into query_log only failed queries (i.e. on memory exceeded error), by using: set log_queries_min_type='EXCEPTION_WHILE_PROCESSING' --- docs/en/operations/settings/settings.md | 18 +++++++++++++++++ src/Core/Settings.h | 2 +- src/Core/SettingsCollection.cpp | 7 +++++++ src/Core/SettingsCollection.h | 10 ++++++++++ src/Interpreters/QueryLog.h | 9 ++------- src/Interpreters/executeQuery.cpp | 20 +++++++++---------- .../01231_log_queries_min_type.reference | 5 +++++ .../01231_log_queries_min_type.sql | 15 ++++++++++++++ 8 files changed, 68 insertions(+), 18 deletions(-) create mode 100644 tests/queries/0_stateless/01231_log_queries_min_type.reference create mode 100644 tests/queries/0_stateless/01231_log_queries_min_type.sql diff --git a/docs/en/operations/settings/settings.md b/docs/en/operations/settings/settings.md index 69c444ebaef..37b4c713f91 100644 --- a/docs/en/operations/settings/settings.md +++ b/docs/en/operations/settings/settings.md @@ -507,6 +507,24 @@ Example: log_queries=1 ``` +## log\_queries\_min\_type {#settings-log-queries-min-type} + +`query_log` minimal type to log. + +Possible values: +- `QUERY_START` (`=1`) +- `QUERY_FINISH` (`=2`) +- `EXCEPTION_BEFORE_START` (`=3`) +- `EXCEPTION_WHILE_PROCESSING` (`=4`) + +Default value: `QUERY_START`. + +Can be used to limit which entiries will goes to `query_log`, say you are interesting only in errors, then you can use `EXCEPTION_WHILE_PROCESSING`: + +``` text +log_queries_min_type='EXCEPTION_WHILE_PROCESSING' +``` + ## log\_query\_threads {#settings-log-query-threads} Setting up query threads logging. diff --git a/src/Core/Settings.h b/src/Core/Settings.h index 8138af31d5f..725171d4a1b 100644 --- a/src/Core/Settings.h +++ b/src/Core/Settings.h @@ -149,7 +149,7 @@ struct Settings : public SettingsCollection M(SettingInt64, os_thread_priority, 0, "If non zero - set corresponding 'nice' value for query processing threads. Can be used to adjust query priority for OS scheduler.", 0) \ \ M(SettingBool, log_queries, 0, "Log requests and write the log to the system table.", 0) \ - \ + M(SettingLogQueriesType, log_queries_min_type, QueryLogElementType::QUERY_START, "query_log minimal type to log, possible values (from low to high): QUERY_START, QUERY_FINISH, EXCEPTION_BEFORE_START, EXCEPTION_WHILE_PROCESSING.", 0) \ M(SettingUInt64, log_queries_cut_to_length, 100000, "If query length is greater than specified threshold (in bytes), then cut query when writing to query log. Also limit length of printed query in ordinary text log.", 0) \ \ M(SettingDistributedProductMode, distributed_product_mode, DistributedProductMode::DENY, "How are distributed subqueries performed inside IN or JOIN sections?", IMPORTANT) \ diff --git a/src/Core/SettingsCollection.cpp b/src/Core/SettingsCollection.cpp index 6d879b27181..238ac1c3c62 100644 --- a/src/Core/SettingsCollection.cpp +++ b/src/Core/SettingsCollection.cpp @@ -542,6 +542,13 @@ IMPLEMENT_SETTING_ENUM(FormatSettings::DateTimeInputFormat, DATE_TIME_INPUT_FORM M(trace, "trace") IMPLEMENT_SETTING_ENUM(LogsLevel, LOGS_LEVEL_LIST_OF_NAMES, ErrorCodes::BAD_ARGUMENTS) +#define LOG_QUERIES_TYPE_LIST_OF_NAMES(M) \ + M(QUERY_START, "QUERY_START") \ + M(QUERY_FINISH, "QUERY_FINISH") \ + M(EXCEPTION_BEFORE_START, "EXCEPTION_BEFORE_START") \ + M(EXCEPTION_WHILE_PROCESSING, "EXCEPTION_WHILE_PROCESSING") +IMPLEMENT_SETTING_ENUM(QueryLogElementType, LOG_QUERIES_TYPE_LIST_OF_NAMES, ErrorCodes::BAD_ARGUMENTS) + namespace details { diff --git a/src/Core/SettingsCollection.h b/src/Core/SettingsCollection.h index da21412b7c1..d93772e86ed 100644 --- a/src/Core/SettingsCollection.h +++ b/src/Core/SettingsCollection.h @@ -298,6 +298,16 @@ enum class LogsLevel }; using SettingLogsLevel = SettingEnum; +// Make it signed for compatibility with DataTypeEnum8 +enum QueryLogElementType : int8_t +{ + QUERY_START = 1, + QUERY_FINISH = 2, + EXCEPTION_BEFORE_START = 3, + EXCEPTION_WHILE_PROCESSING = 4, +}; +using SettingLogQueriesType = SettingEnum; + enum class SettingsBinaryFormat { diff --git a/src/Interpreters/QueryLog.h b/src/Interpreters/QueryLog.h index 836b37095e9..ec14f5e97fb 100644 --- a/src/Interpreters/QueryLog.h +++ b/src/Interpreters/QueryLog.h @@ -1,6 +1,7 @@ #pragma once #include +#include namespace ProfileEvents @@ -22,13 +23,7 @@ namespace DB /// A struct which will be inserted as row into query_log table struct QueryLogElement { - enum Type : int8_t // Make it signed for compatibility with DataTypeEnum8 - { - QUERY_START = 1, - QUERY_FINISH = 2, - EXCEPTION_BEFORE_START = 3, - EXCEPTION_WHILE_PROCESSING = 4, - }; + using Type = QueryLogElementType; Type type = QUERY_START; diff --git a/src/Interpreters/executeQuery.cpp b/src/Interpreters/executeQuery.cpp index c9c66832f08..68bebb83619 100644 --- a/src/Interpreters/executeQuery.cpp +++ b/src/Interpreters/executeQuery.cpp @@ -157,7 +157,7 @@ static void onExceptionBeforeStart(const String & query_for_logging, Context & c /// Log the start of query execution into the table if necessary. QueryLogElement elem; - elem.type = QueryLogElement::EXCEPTION_BEFORE_START; + elem.type = QueryLogElementType::EXCEPTION_BEFORE_START; elem.event_time = current_time; elem.query_start_time = current_time; @@ -175,7 +175,7 @@ static void onExceptionBeforeStart(const String & query_for_logging, Context & c /// Update performance counters before logging to query_log CurrentThread::finalizePerformanceCounters(); - if (settings.log_queries) + if (settings.log_queries && elem.type >= settings.log_queries_min_type) if (auto query_log = context.getQueryLog()) query_log->add(elem); } @@ -400,7 +400,7 @@ static std::tuple executeQueryImpl( { QueryLogElement elem; - elem.type = QueryLogElement::QUERY_START; + elem.type = QueryLogElementType::QUERY_START; elem.event_time = current_time; elem.query_start_time = current_time; @@ -412,7 +412,7 @@ static std::tuple executeQueryImpl( bool log_queries = settings.log_queries && !internal; /// Log into system table start of query execution, if need. - if (log_queries) + if (log_queries && elem.type >= settings.log_queries_min_type) { if (settings.log_query_settings) elem.query_settings = std::make_shared(context.getSettingsRef()); @@ -422,7 +422,7 @@ static std::tuple executeQueryImpl( } /// Also make possible for caller to log successful query finish and exception during execution. - auto finish_callback = [elem, &context, log_queries] (IBlockInputStream * stream_in, IBlockOutputStream * stream_out) mutable + auto finish_callback = [elem, &context, log_queries, log_queries_min_type = settings.log_queries_min_type] (IBlockInputStream * stream_in, IBlockOutputStream * stream_out) mutable { QueryStatus * process_list_elem = context.getProcessListElement(); @@ -436,7 +436,7 @@ static std::tuple executeQueryImpl( double elapsed_seconds = info.elapsed_seconds; - elem.type = QueryLogElement::QUERY_FINISH; + elem.type = QueryLogElementType::QUERY_FINISH; elem.event_time = time(nullptr); elem.query_duration_ms = elapsed_seconds * 1000; @@ -484,19 +484,19 @@ static std::tuple executeQueryImpl( elem.thread_ids = std::move(info.thread_ids); elem.profile_counters = std::move(info.profile_counters); - if (log_queries) + if (log_queries && elem.type >= log_queries_min_type) { if (auto query_log = context.getQueryLog()) query_log->add(elem); } }; - auto exception_callback = [elem, &context, log_queries, quota(quota)] () mutable + auto exception_callback = [elem, &context, log_queries, log_queries_min_type = settings.log_queries_min_type, quota(quota)] () mutable { if (quota) quota->used(Quota::ERRORS, 1, /* check_exceeded = */ false); - elem.type = QueryLogElement::EXCEPTION_WHILE_PROCESSING; + elem.type = QueryLogElementType::EXCEPTION_WHILE_PROCESSING; elem.event_time = time(nullptr); elem.query_duration_ms = 1000 * (elem.event_time - elem.query_start_time); @@ -529,7 +529,7 @@ static std::tuple executeQueryImpl( logException(context, elem); /// In case of exception we log internal queries also - if (log_queries) + if (log_queries && elem.type >= log_queries_min_type) { if (auto query_log = context.getQueryLog()) query_log->add(elem); diff --git a/tests/queries/0_stateless/01231_log_queries_min_type.reference b/tests/queries/0_stateless/01231_log_queries_min_type.reference new file mode 100644 index 00000000000..a358d022033 --- /dev/null +++ b/tests/queries/0_stateless/01231_log_queries_min_type.reference @@ -0,0 +1,5 @@ +01231_log_queries_min_type/QUERY_START +2 +01231_log_queries_min_type/EXCEPTION_BEFORE_START +2 +3 diff --git a/tests/queries/0_stateless/01231_log_queries_min_type.sql b/tests/queries/0_stateless/01231_log_queries_min_type.sql new file mode 100644 index 00000000000..f2229c94a8a --- /dev/null +++ b/tests/queries/0_stateless/01231_log_queries_min_type.sql @@ -0,0 +1,15 @@ +set log_queries=1; + +select '01231_log_queries_min_type/QUERY_START'; +system flush logs; +select count() from system.query_log where query like '%01231_log_queries_min_type/%' and query not like '%system.query_log%' and event_date = today() and event_time >= now() - interval 1 minute; + +set log_queries_min_type='EXCEPTION_BEFORE_START'; +select '01231_log_queries_min_type/EXCEPTION_BEFORE_START'; +system flush logs; +select count() from system.query_log where query like '%01231_log_queries_min_type/%' and query not like '%system.query_log%' and event_date = today() and event_time >= now() - interval 1 minute; + +set log_queries_min_type='EXCEPTION_WHILE_PROCESSING'; +select '01231_log_queries_min_type/', max(number) from system.numbers limit 1e6 settings max_rows_to_read='100K'; -- { serverError 158; } +system flush logs; +select count() from system.query_log where query like '%01231_log_queries_min_type/%' and query not like '%system.query_log%' and event_date = today() and event_time >= now() - interval 1 minute;