FB8-46: Port v5.1 Extra Stats: Command Timers (facebook#989) (faceboo…

…k#989)

Summary:
Jira issue: https://jira.percona.com/browse/FB8-46

Reference Patch: facebook@f2d6fdc

With additional improvements:
1. Variables moved from global to session from facebook@459f669
2. Added time tracking for "sp_instr_stmt::exec_core", "mysql_open_cursor", "Execute_sql_statement::execute_server_code" and "Prepared_statement::execute" from facebook@4554e16

Adds command, slave_command, pre-exec, parse, and execution timers.

This ports these timers from v5.1 to 5.6, using the new timers.

I also added an mtr test to confirm they are at least partly working.

Originally Reviewed By: chip
Pull Request resolved: facebook#989

Differential Revision: D14883715

Pulled By: yizhang82

include/mysql/plugin_audit.h.pp

@@ -34,7 +34,8 @@
   SHOW_SIGNED_INT,
   SHOW_SIGNED_LONG,
   SHOW_SIGNED_LONGLONG,
-  SHOW_TIMER
+  SHOW_TIMER,
+  SHOW_TIMER_STATUS
 };
 enum enum_mysql_show_scope {
   SHOW_SCOPE_UNDEF,

include/mysql/plugin_auth.h.pp

@@ -25,7 +25,8 @@
   SHOW_SIGNED_INT,
   SHOW_SIGNED_LONG,
   SHOW_SIGNED_LONGLONG,
-  SHOW_TIMER
+  SHOW_TIMER,
+  SHOW_TIMER_STATUS
 };
 enum enum_mysql_show_scope {
   SHOW_SCOPE_UNDEF,

include/mysql/plugin_ftparser.h.pp

@@ -25,7 +25,8 @@
   SHOW_SIGNED_INT,
   SHOW_SIGNED_LONG,
   SHOW_SIGNED_LONGLONG,
-  SHOW_TIMER
+  SHOW_TIMER,
+  SHOW_TIMER_STATUS
 };
 enum enum_mysql_show_scope {
   SHOW_SCOPE_UNDEF,

include/mysql/plugin_keyring.h.pp

@@ -25,7 +25,8 @@
   SHOW_SIGNED_INT,
   SHOW_SIGNED_LONG,
   SHOW_SIGNED_LONGLONG,
-  SHOW_TIMER
+  SHOW_TIMER,
+  SHOW_TIMER_STATUS
 };
 enum enum_mysql_show_scope {
   SHOW_SCOPE_UNDEF,

include/mysql/status_var.h

@@ -58,7 +58,8 @@ enum enum_mysql_show_type {
   SHOW_SIGNED_INT,
   SHOW_SIGNED_LONG,
   SHOW_SIGNED_LONGLONG,
-  SHOW_TIMER
+  SHOW_TIMER,
+  SHOW_TIMER_STATUS
 };
 
 /**

mysql-test/r/counter_vars.result

@@ -0,0 +1,8 @@
+flush status;
+select sleep(1.1);
+sleep(1.1)
+0
+include/assert.inc [Parse_seconds should be smaller than a second.]
+include/assert.inc [Pre_exec_seconds should be smaller than a second.]
+include/assert.inc [Exec_seconds should be bigger than a second.]
+include/assert.inc [Command_seconds should be bigger than a second.]

mysql-test/suite/test_services/r/test_status_var_reader.result

@@ -15,6 +15,8 @@ SELECT VARIABLE_NAME, VARIABLE_VALUE, test_get_status_var(VARIABLE_NAME, 0)
 FROM performance_schema.global_status
 WHERE VARIABLE_VALUE <> test_get_status_var(VARIABLE_NAME, 0) AND
 VARIABLE_NAME NOT IN (
+'Command_seconds',
+'Exec_seconds',
 'Bytes_received',
 'Bytes_sent',
 'Handler_commit',
@@ -32,6 +34,8 @@ SELECT VARIABLE_NAME, VARIABLE_VALUE, test_get_status_var(VARIABLE_NAME, 1)
 FROM performance_schema.session_status
 WHERE VARIABLE_VALUE <> test_get_status_var(VARIABLE_NAME, 1) AND
 VARIABLE_NAME NOT IN (
+'Command_seconds',
+'Exec_seconds',
 'Bytes_received',
 'Bytes_sent',
 'Handler_commit',

mysql-test/suite/test_services/t/test_status_var_reader.test

@@ -24,6 +24,8 @@ SELECT VARIABLE_NAME, VARIABLE_VALUE, test_get_status_var(VARIABLE_NAME, 0)
   FROM performance_schema.global_status
   WHERE VARIABLE_VALUE <> test_get_status_var(VARIABLE_NAME, 0) AND
      VARIABLE_NAME NOT IN (
+        'Command_seconds',
+        'Exec_seconds',
         'Bytes_received',
         'Bytes_sent',
         'Handler_commit',
@@ -44,6 +46,8 @@ SELECT VARIABLE_NAME, VARIABLE_VALUE, test_get_status_var(VARIABLE_NAME, 1)
   FROM performance_schema.session_status
   WHERE VARIABLE_VALUE <> test_get_status_var(VARIABLE_NAME, 1) AND
      VARIABLE_NAME NOT IN (
+        'Command_seconds',
+        'Exec_seconds',
         'Bytes_received',
         'Bytes_sent',
         'Handler_commit',

mysql-test/t/counter_vars.test

@@ -0,0 +1,34 @@
+#Set all to zero
+flush status;
+
+#Start counters
+--let $start_parse = query_get_value(show status like "Parse_seconds", Value, 1)
+--let $start_pre_exec = query_get_value(show status like "Pre_exec_seconds", Value, 1)
+--let $start_exec = query_get_value(show status like "Exec_seconds", Value, 1)
+--let $start_command = query_get_value(show status like "Command_seconds", Value, 1)
+
+#Waste ~1.1 seconds
+select sleep(1.1);
+
+#Get counters
+--let $end_parse = query_get_value(show status like "Parse_seconds", Value, 1)
+--let $end_pre_exec = query_get_value(show status like "Pre_exec_seconds", Value, 1)
+--let $end_exec = query_get_value(show status like "Exec_seconds", Value, 1)
+--let $end_command = query_get_value(show status like "Command_seconds", Value, 1)
+
+#Check sanity
+--let $assert_text= Parse_seconds should be smaller than a second.
+--let $assert_cond= $end_parse - $start_parse < 1.0
+--source include/assert.inc
+
+--let $assert_text= Pre_exec_seconds should be smaller than a second.
+--let $assert_cond= $end_pre_exec - $start_pre_exec < 1.0
+--source include/assert.inc
+
+--let $assert_text= Exec_seconds should be bigger than a second.
+--let $assert_cond= $end_exec - $start_exec > 1.0
+--source include/assert.inc
+
+--let $assert_text= Command_seconds should be bigger than a second.
+--let $assert_cond= $end_command - $start_command > 1.0
+--source include/assert.inc

sql/log_event.cc

@@ -214,6 +214,9 @@ using mysql::binlog::event::checksum_crc32;
 
 #define ILLEGAL_CHARSET_INFO_NUMBER (~0U)
 
+/* Time executing SQL for replication */
+ulonglong command_slave_seconds = 0;
+
 /**
   BINLOG_CHECKSUM variable.
 */
@@ -4857,7 +4860,9 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli,
           thd->copy_status_var(&query_start_status);
         }
 
-        dispatch_sql_command(thd, &parser_state);
+        const ulonglong init_timer = my_timer_now();
+        ulonglong last_timer = init_timer;
+        dispatch_sql_command(thd, &parser_state, &last_timer);
 
         enum_sql_command command = thd->lex->sql_command;
 
@@ -4904,6 +4909,7 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli,
         }
         /* Finalize server status flags after executing a statement. */
         thd->update_slow_query_status();
+        command_slave_seconds += my_timer_since(init_timer);
         log_slow_statement(thd);
       }
 
@@ -9802,6 +9808,7 @@ int Rows_log_event::do_apply_event(Relay_log_info const *rli) {
   DBUG_TRACE;
   TABLE *table = nullptr;
   int error = 0;
+  ulonglong init_timer = my_timer_now();
 
   /*
     'thd' has been set by exec_relay_log_event(), just before calling
@@ -10495,6 +10502,8 @@ int Rows_log_event::do_apply_event(Relay_log_info const *rli) {
     thd->reset_db(current_db_name_saved);
   }  // if (table)
 
+  command_slave_seconds += my_timer_since(init_timer);
+
   if (error) {
     slave_rows_error_report(
         ERROR_LEVEL, error, rli, thd, table, get_type_str(),

sql/mysqld.cc

@@ -11940,6 +11940,10 @@ SHOW_VAR status_vars[] = {
     {"Com_stmt_reprepare",
      (char *)offsetof(System_status_var, com_stmt_reprepare), SHOW_LONG_STATUS,
      SHOW_SCOPE_ALL},
+    {"Command_seconds", (char *)offsetof(System_status_var, command_time),
+     SHOW_TIMER_STATUS, SHOW_SCOPE_ALL},
+    {"Command_slave_seconds", (char *)&command_slave_seconds, SHOW_TIMER,
+     SHOW_SCOPE_ALL},
     {"Compression", (char *)&show_net_compression, SHOW_FUNC,
      SHOW_SCOPE_SESSION},
     {"Compression_algorithm", (char *)&show_net_compression_algorithm,
@@ -12004,6 +12008,8 @@ SHOW_VAR status_vars[] = {
      SHOW_LONG, SHOW_SCOPE_GLOBAL},
     {"Error_log_latest_write", (char *)&log_sink_pfs_latest_timestamp,
      SHOW_LONGLONG, SHOW_SCOPE_GLOBAL},
+    {"Exec_seconds", (char *)offsetof(System_status_var, exec_time),
+     SHOW_TIMER_STATUS, SHOW_SCOPE_ALL},
     {"Flush_commands", (char *)&refresh_version, SHOW_LONG_NOFLUSH,
      SHOW_SCOPE_GLOBAL},
     {"Git_hash", (char *)git_hash, SHOW_CHAR, SHOW_SCOPE_GLOBAL},
@@ -12132,6 +12138,10 @@ SHOW_VAR status_vars[] = {
     {"Opened_table_definitions",
      (char *)offsetof(System_status_var, opened_shares), SHOW_LONGLONG_STATUS,
      SHOW_SCOPE_ALL},
+    {"Parse_seconds", (char *)offsetof(System_status_var, parse_time),
+     SHOW_TIMER_STATUS, SHOW_SCOPE_ALL},
+    {"Pre_exec_seconds", (char *)offsetof(System_status_var, pre_exec_time),
+     SHOW_TIMER_STATUS, SHOW_SCOPE_ALL},
     {"Prepared_stmt_count", (char *)&show_prepared_stmt_count, SHOW_FUNC,
      SHOW_SCOPE_GLOBAL},
     {"Replica_open_temp_tables", (char *)&show_replica_open_temp_tables,

sql/mysqld.h

@@ -407,6 +407,9 @@ extern ulonglong (*my_timer_now)(void);
 inline ulonglong my_timer_since(ulonglong then) {
   return (my_timer_now() - then) - my_timer.overhead;
 }
+inline ulonglong my_timer_difftime(ulonglong start, ulonglong stop) {
+  return (stop - start) - my_timer.overhead;
+}
 /* Get time passed since "then", and update then to now */
 inline ulonglong my_timer_since_and_update(ulonglong *then) {
   ulonglong now = my_timer_now();
@@ -803,6 +806,9 @@ extern MYSQL_PLUGIN_IMPORT char pidfile_name[];
 
 #define mysql_tmpdir (my_tmpdir(&mysql_tmpdir_list))
 
+/* Time handling client commands for replication */
+extern ulonglong command_slave_seconds;
+
 extern bool skip_flush_master_info;
 extern bool skip_flush_relay_worker_info;
 

sql/sp_instr.cc

@@ -1054,6 +1054,7 @@ void sp_instr_stmt::print(const THD *, String *str) {
 }
 
 bool sp_instr_stmt::exec_core(THD *thd, uint *nextp) {
+  ulonglong last_time = my_timer_now();
   LEX *const lex = thd->lex;
   lex->set_sp_current_parsing_ctx(get_parsing_ctx());
   lex->sphead = thd->sp_runtime_ctx->sp;
@@ -1062,7 +1063,7 @@ bool sp_instr_stmt::exec_core(THD *thd, uint *nextp) {
 
   assert(lex->m_sql_cmd == nullptr || lex->m_sql_cmd->is_part_of_sp());
 
-  const bool rc = mysql_execute_command(thd);
+  const bool rc = mysql_execute_command(thd, false, &last_time);
 
   lex->set_sp_current_parsing_ctx(nullptr);
   lex->sphead = nullptr;

sql/sql_class.h

@@ -1593,7 +1593,7 @@ class THD : public MDL_context_owner,
   /**
     Query start time, expressed in microseconds.
   */
-  ulonglong start_utime;
+  ulonglong start_utime, pre_exec_time;
 
  private:
   /**

sql/sql_cursor.cc

@@ -41,6 +41,7 @@
 #include "sql/field.h"
 #include "sql/handler.h"
 #include "sql/item.h"
+#include "sql/mysqld.h"  // my_timer_now
 #include "sql/parse_tree_node_base.h"
 #include "sql/protocol.h"
 #include "sql/query_options.h"
@@ -184,6 +185,7 @@ Query_result *new_cursor_result(MEM_ROOT *mem_root, Query_result *result) {
 
 bool mysql_open_cursor(THD *thd, Query_result *result,
                        Server_side_cursor **pcursor) {
+  ulonglong last_time = my_timer_now();
   sql_digest_state *parent_digest;
   PSI_statement_locker *parent_locker;
   Query_result_materialize *result_materialize = nullptr;
@@ -234,7 +236,7 @@ bool mysql_open_cursor(THD *thd, Query_result *result,
   thd->m_statement_psi = nullptr;
   DBUG_EXECUTE_IF("bug33218625_kill_injection", thd->killed = THD::KILL_QUERY;);
 
-  const bool rc = mysql_execute_command(thd);
+  const bool rc = mysql_execute_command(thd, false, &last_time);
 
   thd->m_digest = parent_digest;
   DEBUG_SYNC(thd, "after_table_close");