From 40810baffed3b2180bfb122a397761eda1b46daa Mon Sep 17 00:00:00 2001 From: Monty Date: Sun, 31 Dec 2023 12:41:25 +0200 Subject: [PATCH] MDEV-33144 Implement the Percona variable slow_query_log_always_write_time This task is inspired by the Percona implementation of slow_query_log_always_write_time. This task implements the variable log_slow_always_query_time (name matching other MariaDB variables using the slow query log). The default value for the variable is 31536000, which makes MariaDB compatible with older installations. For queries with execution time longer than log_slow_always_query_time the variables log_slow_rate_limit and log_slow_min_examined_row_limit will be ignored and the query will be written to the slow query log if there is no other limitations (like log_slow_filter etc). Other things: - long_query_time internal variable renamed to log_slow_query_time. - More descriptive information for "log_slow_query_time". --- mysql-test/main/log_slow.result | 1 + .../main/log_slow_always_query_time.result | 22 ++++++++ .../main/log_slow_always_query_time.test | 36 ++++++++++++ mysql-test/main/mysqld--help.result | 17 ++++-- .../sys_vars/r/sysvars_server_embedded.result | 14 ++++- .../r/sysvars_server_notembedded.result | 14 ++++- sql/mysqld.cc | 6 +- sql/sql_class.h | 13 ++++- sql/sql_parse.cc | 4 +- sql/sql_prepare.cc | 2 +- sql/sys_vars.cc | 56 ++++++++++++++----- 11 files changed, 154 insertions(+), 31 deletions(-) create mode 100644 mysql-test/main/log_slow_always_query_time.result create mode 100644 mysql-test/main/log_slow_always_query_time.test diff --git a/mysql-test/main/log_slow.result b/mysql-test/main/log_slow.result index 2ec8c91e863..6c3bc3589ac 100644 --- a/mysql-test/main/log_slow.result +++ b/mysql-test/main/log_slow.result @@ -11,6 +11,7 @@ select @@log_slow_verbosity; show variables like "log_slow%"; Variable_name Value log_slow_admin_statements ON +log_slow_always_query_time 31536000.000000 log_slow_disabled_statements sp log_slow_filter admin,filesort,filesort_on_disk,filesort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk log_slow_max_warnings 10 diff --git a/mysql-test/main/log_slow_always_query_time.result b/mysql-test/main/log_slow_always_query_time.result new file mode 100644 index 00000000000..8994ad6d3ce --- /dev/null +++ b/mysql-test/main/log_slow_always_query_time.result @@ -0,0 +1,22 @@ +select @@session.log_slow_always_query_time; +@@session.log_slow_always_query_time +31536000.000000 +SET GLOBAL log_slow_always_query_time= 20.2; +SET SESSION log_slow_always_query_time=20.2; +select @@global.log_slow_always_query_time, @@session.log_slow_always_query_time; +@@global.log_slow_always_query_time @@session.log_slow_always_query_time +20.200000 20.200000 +set GLOBAL log_slow_always_query_time= default; +SET log_slow_query_time=0.5; +SET log_slow_rate_limit=999; +SET log_slow_always_query_time=1.5; +SET log_slow_min_examined_row_limit= 100; +[slow_log_start.inc] log_slow_always_query_time-1 +SELECT sleep(2) as 'this-should-be-logged'; +this-should-be-logged +0 +SELECT sleep(1) as 'this-should-not-be-logged'; +this-should-not-be-logged +0 +[log_grep.inc] file: log_slow_always_query_time-1 pattern: this-should expected_matches: 1 +[log_grep.inc] lines: 1 diff --git a/mysql-test/main/log_slow_always_query_time.test b/mysql-test/main/log_slow_always_query_time.test new file mode 100644 index 00000000000..33e5a47c4bd --- /dev/null +++ b/mysql-test/main/log_slow_always_query_time.test @@ -0,0 +1,36 @@ +--source include/not_valgrind.inc +# We cannot use ps2 protocol as the test is counting number of executions +--disable_ps2_protocol +# View protocol disabled as it remove the tag from the SELECT query +--disable_view_protocol + +# +# Test log_slow_always_query_time variable usage +# + +--source include/log_slow_prepare.inc + +--let $log_slow_prefix=log_slow_always_query_time +--let $log_file=$log_slow_prefix-1 + +select @@session.log_slow_always_query_time; +SET GLOBAL log_slow_always_query_time= 20.2; +SET SESSION log_slow_always_query_time=20.2; +select @@global.log_slow_always_query_time, @@session.log_slow_always_query_time; +set GLOBAL log_slow_always_query_time= default; + +SET log_slow_query_time=0.5; +SET log_slow_rate_limit=999; +SET log_slow_always_query_time=1.5; +SET log_slow_min_examined_row_limit= 100; + +--source include/log_slow_start.inc +SELECT sleep(2) as 'this-should-be-logged'; +SELECT sleep(1) as 'this-should-not-be-logged'; + +--let grep_pattern=this-should +--let $log_expected_matches=1 +--source include/log_grep.inc + +--source include/log_slow_cleanup.inc +--enable_ps2_protocol diff --git a/mysql-test/main/mysqld--help.result b/mysql-test/main/mysqld--help.result index 16415098e62..696912c0f8c 100644 --- a/mysql-test/main/mysqld--help.result +++ b/mysql-test/main/mysqld--help.result @@ -545,6 +545,14 @@ The following specify which files/extra groups are read (specified before remain Deprecated, will be removed in a future release. Please use --log-slow-filter instead. (Defaults to on; use --skip-log-slow-admin-statements to disable.) + --log-slow-always-query-time=# + Queries slower than log_slow_always_query_time are not + affected by log_slow_rate_limit or + log_slow_min_examined_row_limit. Query will be logged if + execution time of the query is longer than + log_slow_query_time and log_slow_always_query_time. The + argument will be treated as a decimal value with + microsecond precision --log-slow-disabled-statements=name Don't log certain types of statements to slow log. Any combination of: admin, call, slave, sp, or ALL to set all @@ -576,7 +584,8 @@ The following specify which files/extra groups are read (specified before remain Log all queries that have taken more than log_slow_query_time seconds to execute to the slow query log file. The argument will be treated as a decimal value - with microsecond precision + with microsecond precision. Affected by + log_slow_rate_limit and log_slow_min_examined_row_limit --log-slow-rate-limit=# Write to slow log every #th slow query. Set to 1 to log everything. Increase it to reduce the size of the slow or @@ -598,10 +607,7 @@ The following specify which files/extra groups are read (specified before remain Log some non-critical warnings to the error log. Value can be between 0 and 11. Higher values mean more verbosity - --long-query-time=# Alias for log_slow_query_time. Log all queries that have - taken more than long_query_time seconds to execute to the - slow query log file. The argument will be treated as a - decimal value with microsecond precision + --long-query-time=# Alias for log_slow_query_time --low-priority-updates INSERT/DELETE/UPDATE has lower priority than selects --lower-case-table-names[=#] @@ -1768,6 +1774,7 @@ log-queries-not-using-indexes FALSE log-short-format FALSE log-slave-updates FALSE log-slow-admin-statements TRUE +log-slow-always-query-time 3.1536e+07 log-slow-disabled-statements sp log-slow-filter admin,filesort,filesort_on_disk,filesort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk log-slow-max-warnings 10 diff --git a/mysql-test/suite/sys_vars/r/sysvars_server_embedded.result b/mysql-test/suite/sys_vars/r/sysvars_server_embedded.result index 2ba5f9e2e6d..58ec9997457 100644 --- a/mysql-test/suite/sys_vars/r/sysvars_server_embedded.result +++ b/mysql-test/suite/sys_vars/r/sysvars_server_embedded.result @@ -1732,6 +1732,16 @@ NUMERIC_BLOCK_SIZE NULL ENUM_VALUE_LIST OFF,ON READ_ONLY NO COMMAND_LINE_ARGUMENT OPTIONAL +VARIABLE_NAME LOG_SLOW_ALWAYS_QUERY_TIME +VARIABLE_SCOPE SESSION +VARIABLE_TYPE DOUBLE +VARIABLE_COMMENT Queries slower than log_slow_always_query_time are not affected by log_slow_rate_limit or log_slow_min_examined_row_limit. Query will be logged if execution time of the query is longer than log_slow_query_time and log_slow_always_query_time. The argument will be treated as a decimal value with microsecond precision +NUMERIC_MIN_VALUE 0 +NUMERIC_MAX_VALUE 31536000 +NUMERIC_BLOCK_SIZE NULL +ENUM_VALUE_LIST NULL +READ_ONLY NO +COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_SLOW_DISABLED_STATEMENTS VARIABLE_SCOPE SESSION VARIABLE_TYPE SET @@ -1795,7 +1805,7 @@ COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_SLOW_QUERY_TIME VARIABLE_SCOPE SESSION VARIABLE_TYPE DOUBLE -VARIABLE_COMMENT Log all queries that have taken more than log_slow_query_time seconds to execute to the slow query log file. The argument will be treated as a decimal value with microsecond precision +VARIABLE_COMMENT Log all queries that have taken more than log_slow_query_time seconds to execute to the slow query log file. The argument will be treated as a decimal value with microsecond precision. Affected by log_slow_rate_limit and log_slow_min_examined_row_limit NUMERIC_MIN_VALUE 0 NUMERIC_MAX_VALUE 31536000 NUMERIC_BLOCK_SIZE NULL @@ -1845,7 +1855,7 @@ COMMAND_LINE_ARGUMENT OPTIONAL VARIABLE_NAME LONG_QUERY_TIME VARIABLE_SCOPE SESSION VARIABLE_TYPE DOUBLE -VARIABLE_COMMENT Alias for log_slow_query_time. Log all queries that have taken more than long_query_time seconds to execute to the slow query log file. The argument will be treated as a decimal value with microsecond precision +VARIABLE_COMMENT Alias for log_slow_query_time NUMERIC_MIN_VALUE 0 NUMERIC_MAX_VALUE 31536000 NUMERIC_BLOCK_SIZE NULL diff --git a/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.result b/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.result index 01bd23b062a..76fe78b9b55 100644 --- a/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.result +++ b/mysql-test/suite/sys_vars/r/sysvars_server_notembedded.result @@ -1922,6 +1922,16 @@ NUMERIC_BLOCK_SIZE NULL ENUM_VALUE_LIST OFF,ON READ_ONLY NO COMMAND_LINE_ARGUMENT OPTIONAL +VARIABLE_NAME LOG_SLOW_ALWAYS_QUERY_TIME +VARIABLE_SCOPE SESSION +VARIABLE_TYPE DOUBLE +VARIABLE_COMMENT Queries slower than log_slow_always_query_time are not affected by log_slow_rate_limit or log_slow_min_examined_row_limit. Query will be logged if execution time of the query is longer than log_slow_query_time and log_slow_always_query_time. The argument will be treated as a decimal value with microsecond precision +NUMERIC_MIN_VALUE 0 +NUMERIC_MAX_VALUE 31536000 +NUMERIC_BLOCK_SIZE NULL +ENUM_VALUE_LIST NULL +READ_ONLY NO +COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_SLOW_DISABLED_STATEMENTS VARIABLE_SCOPE SESSION VARIABLE_TYPE SET @@ -1985,7 +1995,7 @@ COMMAND_LINE_ARGUMENT REQUIRED VARIABLE_NAME LOG_SLOW_QUERY_TIME VARIABLE_SCOPE SESSION VARIABLE_TYPE DOUBLE -VARIABLE_COMMENT Log all queries that have taken more than log_slow_query_time seconds to execute to the slow query log file. The argument will be treated as a decimal value with microsecond precision +VARIABLE_COMMENT Log all queries that have taken more than log_slow_query_time seconds to execute to the slow query log file. The argument will be treated as a decimal value with microsecond precision. Affected by log_slow_rate_limit and log_slow_min_examined_row_limit NUMERIC_MIN_VALUE 0 NUMERIC_MAX_VALUE 31536000 NUMERIC_BLOCK_SIZE NULL @@ -2035,7 +2045,7 @@ COMMAND_LINE_ARGUMENT OPTIONAL VARIABLE_NAME LONG_QUERY_TIME VARIABLE_SCOPE SESSION VARIABLE_TYPE DOUBLE -VARIABLE_COMMENT Alias for log_slow_query_time. Log all queries that have taken more than long_query_time seconds to execute to the slow query log file. The argument will be treated as a decimal value with microsecond precision +VARIABLE_COMMENT Alias for log_slow_query_time NUMERIC_MIN_VALUE 0 NUMERIC_MAX_VALUE 31536000 NUMERIC_BLOCK_SIZE NULL diff --git a/sql/mysqld.cc b/sql/mysqld.cc index a7b5f4b9a54..cf268f4b8a1 100644 --- a/sql/mysqld.cc +++ b/sql/mysqld.cc @@ -8941,10 +8941,12 @@ static int get_options(int *argc_ptr, char ***argv_ptr) if (my_assert_on_error) debug_assert_if_crashed_table= 1; - global_system_variables.long_query_time= (ulonglong) - (global_system_variables.long_query_time_double * 1e6 + 0.1); + global_system_variables.log_slow_query_time= (ulonglong) + (global_system_variables.log_slow_query_time_double * 1e6 + 0.1); global_system_variables.max_statement_time= (ulonglong) (global_system_variables.max_statement_time_double * 1e6 + 0.1); + global_system_variables.log_slow_always_query_time= (ulonglong) + (global_system_variables.log_slow_always_query_time_double * 1e6 + 0.1); if (opt_short_log_format) opt_specialflag|= SPECIAL_SHORT_LOG_FORMAT; diff --git a/sql/sql_class.h b/sql/sql_class.h index 6c54ca492a1..6b533ac6e78 100644 --- a/sql/sql_class.h +++ b/sql/sql_class.h @@ -714,7 +714,8 @@ typedef struct system_variables ulonglong max_heap_table_size; ulonglong tmp_memory_table_size; ulonglong tmp_disk_table_size; - ulonglong long_query_time; + ulonglong log_slow_query_time; + ulonglong log_slow_always_query_time; ulonglong max_statement_time; ulonglong optimizer_switch; ulonglong optimizer_trace; @@ -743,7 +744,8 @@ typedef struct system_variables ulonglong max_tmp_space_usage; double optimizer_where_cost, optimizer_scan_setup_cost; - double long_query_time_double, max_statement_time_double; + double log_slow_query_time_double, max_statement_time_double; + double log_slow_always_query_time_double; double sample_percentage; ha_rows select_limit; @@ -4438,9 +4440,14 @@ public: void update_server_status() { set_time_for_next_stage(); - if (utime_after_query >= utime_after_lock + variables.long_query_time) + if (utime_after_query >= utime_after_lock + variables.log_slow_query_time) server_status|= SERVER_QUERY_WAS_SLOW; } + /* True if query took longer than log_slow_always_query_time */ + bool log_slow_always_query_time() + { + return (utime_after_query >= utime_after_lock + variables.log_slow_always_query_time); + } inline ulonglong found_rows(void) { return limit_found_rows; diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc index 86eee870faa..073d3c38511 100644 --- a/sql/sql_parse.cc +++ b/sql/sql_parse.cc @@ -2552,7 +2552,8 @@ void log_slow_statement(THD *thd) } if ((thd->server_status & SERVER_QUERY_WAS_SLOW) && - thd->get_examined_row_count() >= thd->variables.min_examined_row_limit) + (thd->get_examined_row_count() >= thd->variables.min_examined_row_limit || + thd->log_slow_always_query_time())) { thd->status_var.long_query_count++; @@ -2572,6 +2573,7 @@ void log_slow_statement(THD *thd) this query to the log or not. */ if (thd->variables.log_slow_rate_limit > 1 && + !thd->log_slow_always_query_time() && (global_query_id % thd->variables.log_slow_rate_limit) != 0) goto end; diff --git a/sql/sql_prepare.cc b/sql/sql_prepare.cc index 3dc770cf969..ae26fb42e01 100644 --- a/sql/sql_prepare.cc +++ b/sql/sql_prepare.cc @@ -5097,7 +5097,7 @@ bool Prepared_statement::execute(String *expanded_query, bool open_cursor) E.g., lets consider the following statements SET slow_query_log= 1; - SET @@long_query_time=0.01; + SET @@log_slow_query_time=0.01; PREPARE stmt FROM 'set statement slow_query_log=0 for select sleep(0.1)'; EXECUTE stmt; diff --git a/sql/sys_vars.cc b/sql/sys_vars.cc index 9182a41c0a8..e5caa64688d 100644 --- a/sql/sys_vars.cc +++ b/sql/sys_vars.cc @@ -1626,38 +1626,64 @@ static Sys_var_ulong Sys_log_warnings( CMD_LINE(OPT_ARG, 'W'), VALID_RANGE(0, UINT_MAX), DEFAULT(2), BLOCK_SIZE(1)); -static bool update_cached_long_query_time(sys_var *self, THD *thd, - enum_var_type type) + +static bool update_cached_log_slow_query_time(sys_var *self, THD *thd, + enum_var_type type) { if (type == OPT_SESSION) - thd->variables.long_query_time= - double2ulonglong(thd->variables.long_query_time_double * 1e6); + thd->variables.log_slow_query_time= + double2ulonglong(thd->variables.log_slow_query_time_double * 1e6); else - global_system_variables.long_query_time= - double2ulonglong(global_system_variables.long_query_time_double * 1e6); + global_system_variables.log_slow_query_time= + double2ulonglong(global_system_variables.log_slow_query_time_double * 1e6); + return false; +} + +static bool update_log_slow_always_query_time(sys_var *self, THD *thd, + enum_var_type type) +{ + if (type == OPT_SESSION) + thd->variables.log_slow_always_query_time= + double2ulonglong(thd->variables. + log_slow_always_query_time_double * 1e6); + else + global_system_variables.log_slow_always_query_time= + double2ulonglong(global_system_variables. + log_slow_always_query_time_double * 1e6); return false; } static Sys_var_double Sys_long_query_time( "long_query_time", - "Alias for log_slow_query_time. " - "Log all queries that have taken more than long_query_time seconds " - "to execute to the slow query log file. The argument will be treated " - "as a decimal value with microsecond precision", - SESSION_VAR(long_query_time_double), + "Alias for log_slow_query_time", + SESSION_VAR(log_slow_query_time_double), CMD_LINE(REQUIRED_ARG), VALID_RANGE(0, LONG_TIMEOUT), DEFAULT(10), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0), - ON_UPDATE(update_cached_long_query_time)); + ON_UPDATE(update_cached_log_slow_query_time)); static Sys_var_double Sys_log_slow_query_time( "log_slow_query_time", "Log all queries that have taken more than log_slow_query_time seconds " "to execute to the slow query log file. The argument will be treated " - "as a decimal value with microsecond precision", - SESSION_VAR(long_query_time_double), + "as a decimal value with microsecond precision. " + "Affected by log_slow_rate_limit and log_slow_min_examined_row_limit", + SESSION_VAR(log_slow_query_time_double), CMD_LINE(REQUIRED_ARG), VALID_RANGE(0, LONG_TIMEOUT), DEFAULT(10), NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0), - ON_UPDATE(update_cached_long_query_time)); + ON_UPDATE(update_cached_log_slow_query_time)); + +static Sys_var_double Sys_log_slow_always_query_time( + "log_slow_always_query_time", + "Queries slower than log_slow_always_query_time are not affected " + "by log_slow_rate_limit or log_slow_min_examined_row_limit. Query " + "will be logged if execution time of the query is longer than " + "log_slow_query_time and log_slow_always_query_time. " + "The argument will be treated as a decimal value with microsecond " + "precision", + SESSION_VAR(log_slow_always_query_time_double), + CMD_LINE(REQUIRED_ARG), VALID_RANGE(0, LONG_TIMEOUT), DEFAULT(LONG_TIMEOUT), + NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0), + ON_UPDATE(update_log_slow_always_query_time)); static bool update_cached_max_statement_time(sys_var *self, THD *thd, enum_var_type type)