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".

Author: montywi

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

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

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

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

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

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

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;

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 @@ class THD: public THD_count, /* this must be first */
   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;

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;
 

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;