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".
2025-01-15 19:42:28 +01:00 · 2023-12-31 12:41:25 +02:00 · 2023-12-31 12:41:25 +02:00 · 40810baffe
commit 40810baffe
parent bf9662f6fa
11 changed files with 154 additions and 31 deletions
--- 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
--- a/mysql-test/main/log_slow_always_query_time.result
+++ 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
--- a/mysql-test/main/log_slow_always_query_time.test
+++ 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
--- 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
--- 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
--- 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
--- 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;
--- 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;
--- 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;

--- 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;

--- 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)