MDEV-35720 Add query_time to statistics

Added Query_time (total time spent running queries) to status_variables.

Other things:
- Added SHOW_MICROSECOND_STATUS type that shows an ulonglong variable
  in microseconds converted to a double (in seconds).
- Changed Busy_time and Cpu_time to use SHOW_MICROSECOND_STATUS, which
  simplified the code and avoids some double divisions for each query.

Reviewed-by: Sergei Golubchik <serg@mariadb.org>

mysql-test/main/log_state.result

@@ -275,6 +275,42 @@ SELECT @@general_log_file = @my_glf;
 @@general_log_file = @my_glf
 1
 SET GLOBAL general_log_file = @old_general_log_file;
+#
+# MDEV-35720 Add query_time to statistics
+#
+connect  con2,localhost,root,,;
+set @s1=(select variable_value from information_schema.session_status where
+variable_name='query_time');
+select sleep(3) into @a;
+set @s2=(select variable_value from information_schema.session_status where
+variable_name='query_time');
+set @s3=(select variable_value from information_schema.global_status where
+variable_name='query_time');
+select @s1 >= 0.00 and @s1 <= 2.00 as "should be true";
+should be true
+1
+select @s2 >= 2.00 and @s2 < 10.00 as "should be true";
+should be true
+1
+select @s3 >= 3.00 as "should be true";
+should be true
+1
+disconnect con2;
+connection default;
+create procedure p1()
+begin
+select sleep(1) into @a;
+select sleep(2) into @a;
+end|
+connect  con2,localhost,root,,;
+call p1();
+set @s1=(select variable_value from information_schema.session_status where
+variable_name='query_time');
+select @s1 > 2.00 and @s1 < 10.00 as "should be true";
+should be true
+1
+disconnect con2;
+connection default;
 disconnect con1;
 connection default;
 SET GLOBAL long_query_time = @save_long_query_time;

mysql-test/main/log_state.test

@@ -321,6 +321,45 @@ SET GLOBAL general_log_file = @old_general_log_file;
 
 --enable_ps_protocol
 
+--echo #
+--echo # MDEV-35720 Add query_time to statistics
+--echo #
+
+connect (con2,localhost,root,,);
+set @s1=(select variable_value from information_schema.session_status where
+variable_name='query_time');
+select sleep(3) into @a;
+set @s2=(select variable_value from information_schema.session_status where
+variable_name='query_time');
+set @s3=(select variable_value from information_schema.global_status where
+variable_name='query_time');
+
+select @s1 >= 0.00 and @s1 <= 2.00 as "should be true";
+select @s2 >= 2.00 and @s2 < 10.00 as "should be true";
+select @s3 >= 3.00 as "should be true";
+
+# select @s1,@s2,@s3;
+disconnect con2;
+connection default;
+
+delimiter |;
+create procedure p1()
+begin
+select sleep(1) into @a;
+select sleep(2) into @a;
+end|
+delimiter ;|
+
+connect (con2,localhost,root,,);
+call p1();
+set @s1=(select variable_value from information_schema.session_status where
+variable_name='query_time');
+select @s1 > 2.00 and @s1 < 10.00 as "should be true";
+
+# select @s1;
+disconnect con2;
+connection default;
+
 #
 # Cleanup
 #

sql/mysqld.cc

@@ -6913,7 +6913,6 @@ static int show_queries(THD *thd, SHOW_VAR *var, void *,
   return 0;
 }
 
-
 static int show_net_compression(THD *thd, SHOW_VAR *var, void *,
                                 system_status_var *, enum_var_type)
 {
@@ -7430,7 +7429,7 @@ SHOW_VAR status_vars[]= {
   {"Binlog_cache_use",         (char*) &binlog_cache_use,       SHOW_LONG},
   {"Binlog_stmt_cache_disk_use",(char*) &binlog_stmt_cache_disk_use,  SHOW_LONG},
   {"Binlog_stmt_cache_use",    (char*) &binlog_stmt_cache_use,       SHOW_LONG},
-  {"Busy_time",                (char*) offsetof(STATUS_VAR, busy_time), SHOW_DOUBLE_STATUS},
+  {"Busy_time",                (char*) offsetof(STATUS_VAR, busy_time), SHOW_MICROSECOND_STATUS},
   {"Bytes_received",           (char*) offsetof(STATUS_VAR, bytes_received), SHOW_LONGLONG_STATUS},
   {"Bytes_sent",               (char*) offsetof(STATUS_VAR, bytes_sent), SHOW_LONGLONG_STATUS},
   {"Column_compressions",      (char*) offsetof(STATUS_VAR, column_compressions), SHOW_LONG_STATUS},
@@ -7444,7 +7443,7 @@ SHOW_VAR status_vars[]= {
   {"Connection_errors_peer_address", (char*) &connection_errors_peer_addr, SHOW_LONG},
   {"Connection_errors_select", (char*) &connection_errors_select, SHOW_LONG},
   {"Connection_errors_tcpwrap", (char*) &connection_errors_tcpwrap, SHOW_LONG},
-  {"Cpu_time",                 (char*) offsetof(STATUS_VAR, cpu_time), SHOW_DOUBLE_STATUS},
+  {"Cpu_time",                 (char*) offsetof(STATUS_VAR, cpu_time), SHOW_MICROSECOND_STATUS},
   {"Created_tmp_disk_tables",  (char*) offsetof(STATUS_VAR, created_tmp_disk_tables_), SHOW_LONG_STATUS},
   {"Created_tmp_files",	       (char*) &my_tmp_file_created,	SHOW_LONG},
   {"Created_tmp_tables",       (char*) offsetof(STATUS_VAR, created_tmp_tables_), SHOW_LONG_STATUS},
@@ -7561,6 +7560,7 @@ SHOW_VAR status_vars[]= {
   {"Qcache_total_blocks",      (char*) &query_cache.total_blocks, SHOW_LONG_NOFLUSH},
 #endif /*HAVE_QUERY_CACHE*/
   {"Queries",                  (char*) &show_queries,            SHOW_SIMPLE_FUNC},
+  {"Query_time",               (char*) offsetof(STATUS_VAR, query_time), SHOW_MICROSECOND_STATUS},
   {"Questions",                (char*) offsetof(STATUS_VAR, questions), SHOW_LONG_STATUS},
 #ifdef HAVE_REPLICATION
   {"Rpl_status",               (char*) &show_rpl_status,          SHOW_SIMPLE_FUNC},

sql/sql_class.cc

@@ -1419,7 +1419,10 @@ void THD::update_stats(void)
 void THD::update_all_stats()
 {
   ulonglong end_cpu_time, end_utime;
-  double busy_time, cpu_time;
+  ulonglong busy_time, cpu_time;
+
+  status_var_add(status_var.query_time,
+                 (utime_after_query - utime_after_lock));
 
   /* This is set at start of query if opt_userstat_running was set */
   if (!userstat_running)
@@ -1427,10 +1430,10 @@ void THD::update_all_stats()
 
   end_cpu_time= my_getcputime();
   end_utime=    microsecond_interval_timer();
-  busy_time= (end_utime - start_utime) / 1000000.0;
+  busy_time= end_utime - start_utime;
-  cpu_time=  (end_cpu_time - start_cpu_time) / 10000000.0;
+  cpu_time=  end_cpu_time - start_cpu_time;
   /* In case there are bad values, 2629743 is the #seconds in a month. */
-  if (cpu_time > 2629743.0)
+  if (cpu_time > 2629743000000ULL)
     cpu_time= 0;
   status_var_add(status_var.cpu_time, cpu_time);
   status_var_add(status_var.busy_time, busy_time);
@@ -1853,6 +1856,7 @@ void add_to_status(STATUS_VAR *to_var, STATUS_VAR *from_var)
   to_var->table_open_cache_hits+= from_var->table_open_cache_hits;
   to_var->table_open_cache_misses+= from_var->table_open_cache_misses;
   to_var->table_open_cache_overflows+= from_var->table_open_cache_overflows;
+  to_var->query_time+=          from_var->query_time;
 
   /*
     Update global_memory_used. We have to do this with atomic_add as the
@@ -1910,6 +1914,7 @@ void add_diff_to_status(STATUS_VAR *to_var, STATUS_VAR *from_var,
                                     dec_var->table_open_cache_misses;
   to_var->table_open_cache_overflows+= from_var->table_open_cache_overflows -
                                        dec_var->table_open_cache_overflows;
+  to_var->query_time+=            from_var->query_time - dec_var->query_time;
 
   /*
     We don't need to accumulate memory_used as these are not reset or used by

sql/sql_class.h

@@ -1046,8 +1046,8 @@ typedef struct system_status_var
   ulonglong table_open_cache_misses;
   ulonglong table_open_cache_overflows;
   ulonglong send_metadata_skips;
+  ulonglong cpu_time, busy_time, query_time;
   double last_query_cost;
-  double cpu_time, busy_time;
   uint32 threads_running;
   /* Don't initialize */
   /* Memory used for thread local storage */

sql/sql_plugin.h

@@ -26,7 +26,7 @@
             SHOW_LONG_NOFLUSH, SHOW_LEX_STRING, SHOW_ATOMIC_COUNTER_UINT32_T, \
       /* SHOW_*_STATUS must be at the end, SHOW_LONG_STATUS being first */ \
             SHOW_LONG_STATUS, SHOW_DOUBLE_STATUS, SHOW_LONGLONG_STATUS, \
-            SHOW_UINT32_STATUS
+            SHOW_UINT32_STATUS, SHOW_MICROSECOND_STATUS,
 #include "mariadb.h"
 #undef SHOW_always_last
 

sql/sql_show.cc

@@ -3737,6 +3737,16 @@ const char* get_one_variable(THD *thd,
   case SHOW_SLONGLONG:
     end= longlong10_to_str(*value.as_longlong, buff, -10);
     break;
+  case SHOW_MICROSECOND_STATUS:
+  {
+    /* Show a long long as double in seconds */
+    ulonglong microseconds;
+    value.as_char= status_var_value.as_char + value.as_intptr;
+    microseconds= *value.as_longlong;
+    /* 6 is the default precision for '%f' in sprintf() */
+    end= buff + my_fcvt(microseconds / 1000000.0, 6, buff, NULL);
+    break;
+  }
   case SHOW_HAVE:
     {
       pos= show_comp_option_name[(int) *value.as_show_comp_options];