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)