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

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

Reference Patch: f2d6fdc

With additional improvements:
1. Variables moved from global to session from 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 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: #989

Reviewed By: yizhang82

Differential Revision: D14883715

Pulled By: yizhang82

fbshipit-source-id: 0408f15

include/mysql/plugin_audit.h.pp

@@ -32,7 +32,8 @@
   SHOW_LONGLONG_STATUS,
   SHOW_LEX_STRING,
   SHOW_SIGNED_LONG,
-  SHOW_TIMER
+  SHOW_TIMER,
+  SHOW_TIMER_STATUS
 };
 enum enum_mysql_show_scope {
   SHOW_SCOPE_UNDEF,

include/mysql/plugin_auth.h.pp

@@ -23,7 +23,8 @@
   SHOW_LONGLONG_STATUS,
   SHOW_LEX_STRING,
   SHOW_SIGNED_LONG,
-  SHOW_TIMER
+  SHOW_TIMER,
+  SHOW_TIMER_STATUS
 };
 enum enum_mysql_show_scope {
   SHOW_SCOPE_UNDEF,

include/mysql/plugin_ftparser.h.pp

@@ -23,7 +23,8 @@
   SHOW_LONGLONG_STATUS,
   SHOW_LEX_STRING,
   SHOW_SIGNED_LONG,
-  SHOW_TIMER
+  SHOW_TIMER,
+  SHOW_TIMER_STATUS
 };
 enum enum_mysql_show_scope {
   SHOW_SCOPE_UNDEF,

include/mysql/plugin_keyring.h.pp

@@ -23,7 +23,8 @@
   SHOW_LONGLONG_STATUS,
   SHOW_LEX_STRING,
   SHOW_SIGNED_LONG,
-  SHOW_TIMER
+  SHOW_TIMER,
+  SHOW_TIMER_STATUS
 };
 enum enum_mysql_show_scope {
   SHOW_SCOPE_UNDEF,

include/mysql/status_var.h

@@ -53,7 +53,8 @@ enum enum_mysql_show_type {
   SHOW_LONGLONG_STATUS,
   SHOW_LEX_STRING,
   SHOW_SIGNED_LONG,
-  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/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

@@ -175,6 +175,9 @@ PSI_memory_key key_memory_Rows_query_log_event_rows_query;
 using std::max;
 using std::min;
 
+/* Time executing SQL for replication */
+ulonglong command_slave_seconds = 0;
+
 /**
   BINLOG_CHECKSUM variable.
 */
@@ -4611,7 +4614,9 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli,
           query_start_status = thd->status_var;
         }
 
-        mysql_parse(thd, &parser_state, true);
+        const ulonglong init_timer = my_timer_now();
+        ulonglong last_timer = init_timer;
+        mysql_parse(thd, &parser_state, true, &last_timer);
 
         enum_sql_command command = thd->lex->sql_command;
 
@@ -4658,6 +4663,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, query_start_status_ptr);
       }
 
@@ -9201,6 +9207,7 @@ int Rows_log_event::do_apply_event(Relay_log_info const *rli) {
   DBUG_ENTER("Rows_log_event::do_apply_event(Relay_log_info*)");
   TABLE *table = NULL;
   int error = 0;
+  ulonglong init_timer = my_timer_now();
 
   /*
     'thd' has been set by exec_relay_log_event(), just before calling
@@ -9767,6 +9774,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

@@ -7907,59 +7907,78 @@ static int show_connection_errors_tcpwrap(THD *, SHOW_VAR *var, char *buff) {
   return 0;
 }
 
-static int show_connection_errors_net_ER_NET_ERROR_ON_WRITE(THD *, SHOW_VAR *var, char *buff) {
+static int show_connection_errors_net_ER_NET_ERROR_ON_WRITE(THD *,
+                                                            SHOW_VAR *var,
+                                                            char *buff) {
   var->type = SHOW_LONG;
   var->value = buff;
   long *value = reinterpret_cast<long *>(buff);
-  *value = static_cast<long>(connection_errors_net_ER_NET_ERROR_ON_WRITE.load());
+  *value =
+      static_cast<long>(connection_errors_net_ER_NET_ERROR_ON_WRITE.load());
   return 0;
 }
 
-static int show_connection_errors_net_ER_NET_PACKETS_OUT_OF_ORDER(THD *, SHOW_VAR *var, char *buff) {
+static int show_connection_errors_net_ER_NET_PACKETS_OUT_OF_ORDER(THD *,
+                                                                  SHOW_VAR *var,
+                                                                  char *buff) {
   var->type = SHOW_LONG;
   var->value = buff;
   long *value = reinterpret_cast<long *>(buff);
-  *value = static_cast<long>(connection_errors_net_ER_NET_PACKETS_OUT_OF_ORDER.load());
+  *value = static_cast<long>(
+      connection_errors_net_ER_NET_PACKETS_OUT_OF_ORDER.load());
   return 0;
 }
 
-static int show_connection_errors_net_ER_NET_PACKET_TOO_LARGE(THD *, SHOW_VAR *var, char *buff) {
+static int show_connection_errors_net_ER_NET_PACKET_TOO_LARGE(THD *,
+                                                              SHOW_VAR *var,
+                                                              char *buff) {
   var->type = SHOW_LONG;
   var->value = buff;
   long *value = reinterpret_cast<long *>(buff);
-  *value = static_cast<long>(connection_errors_net_ER_NET_PACKET_TOO_LARGE.load());
+  *value =
+      static_cast<long>(connection_errors_net_ER_NET_PACKET_TOO_LARGE.load());
   return 0;
 }
 
-static int show_connection_errors_net_ER_NET_READ_ERROR(THD *, SHOW_VAR *var, char *buff) {
+static int show_connection_errors_net_ER_NET_READ_ERROR(THD *, SHOW_VAR *var,
+                                                        char *buff) {
   var->type = SHOW_LONG;
   var->value = buff;
   long *value = reinterpret_cast<long *>(buff);
   *value = static_cast<long>(connection_errors_net_ER_NET_READ_ERROR.load());
   return 0;
 }
 
-static int show_connection_errors_net_ER_NET_READ_INTERRUPTED(THD *, SHOW_VAR *var, char *buff) {
+static int show_connection_errors_net_ER_NET_READ_INTERRUPTED(THD *,
+                                                              SHOW_VAR *var,
+                                                              char *buff) {
   var->type = SHOW_LONG;
   var->value = buff;
   long *value = reinterpret_cast<long *>(buff);
-  *value = static_cast<long>(connection_errors_net_ER_NET_READ_INTERRUPTED.load());
+  *value =
+      static_cast<long>(connection_errors_net_ER_NET_READ_INTERRUPTED.load());
   return 0;
 }
 
-static int show_connection_errors_net_ER_NET_UNCOMPRESS_ERROR(THD *, SHOW_VAR *var, char *buff) {
+static int show_connection_errors_net_ER_NET_UNCOMPRESS_ERROR(THD *,
+                                                              SHOW_VAR *var,
+                                                              char *buff) {
   var->type = SHOW_LONG;
   var->value = buff;
   long *value = reinterpret_cast<long *>(buff);
-  *value = static_cast<long>(connection_errors_net_ER_NET_UNCOMPRESS_ERROR.load());
+  *value =
+      static_cast<long>(connection_errors_net_ER_NET_UNCOMPRESS_ERROR.load());
   return 0;
 }
 
-static int show_connection_errors_net_ER_NET_WRITE_INTERRUPTED(THD *, SHOW_VAR *var, char *buff) {
+static int show_connection_errors_net_ER_NET_WRITE_INTERRUPTED(THD *,
+                                                               SHOW_VAR *var,
+                                                               char *buff) {
   var->type = SHOW_LONG;
   var->value = buff;
   long *value = reinterpret_cast<long *>(buff);
-  *value = static_cast<long>(connection_errors_net_ER_NET_WRITE_INTERRUPTED.load());
+  *value =
+      static_cast<long>(connection_errors_net_ER_NET_WRITE_INTERRUPTED.load());
   return 0;
 }
 
@@ -8592,6 +8611,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},
     {"Connections", (char *)&show_thread_id_count, SHOW_FUNC,
@@ -8644,6 +8667,8 @@ SHOW_VAR status_vars[] = {
      SHOW_LONG_NOFLUSH, SHOW_SCOPE_GLOBAL},
     {"Delayed_writes", (char *)&delayed_insert_writes, SHOW_LONG,
      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},
     {"Handler_commit", (char *)offsetof(System_status_var, ha_commit_count),
@@ -8757,6 +8782,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},
     {"Queries", (char *)&show_queries, SHOW_FUNC, SHOW_SCOPE_ALL},

sql/mysqld.h

@@ -349,6 +349,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();
@@ -738,6 +741,9 @@ extern char default_binlogfile_name[FN_REFLEN];
 
 #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;
 
 /*

sql/sp_instr.cc

@@ -939,12 +939,14 @@ void sp_instr_stmt::print(String *str) {
 }
 
 bool sp_instr_stmt::exec_core(THD *thd, uint *nextp) {
+  ulonglong last_time = my_timer_now();
+
   thd->lex->set_sp_current_parsing_ctx(get_parsing_ctx());
   thd->lex->sphead = thd->sp_runtime_ctx->sp;
 
   PSI_statement_locker *statement_psi_saved = thd->m_statement_psi;
 
-  bool rc = mysql_execute_command(thd);
+  bool rc = mysql_execute_command(thd, false, &last_time);
 
   thd->lex->set_sp_current_parsing_ctx(NULL);
   thd->lex->sphead = NULL;

sql/sql_class.h

@@ -1267,7 +1267,7 @@ class THD : public MDL_context_owner,
   uint16 peer_port;
   struct timeval start_time;
   struct timeval user_time;
-  ulonglong start_utime, utime_after_lock;
+  ulonglong start_utime, utime_after_lock, pre_exec_time;
   /* record the semisync ack time */
   ulonglong semisync_ack_time = 0;
   /* record the engine commit time */

sql/sql_cursor.cc

@@ -39,6 +39,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"
@@ -134,6 +135,7 @@ bool mysql_open_cursor(THD *thd, Query_result *result,
             new (thd->mem_root) Query_result_materialize(thd, result)))
     return true;
 
+  ulonglong last_time = my_timer_now();
   save_result = lex->result;
 
   lex->result = result_materialize;
@@ -142,7 +144,7 @@ bool mysql_open_cursor(THD *thd, Query_result *result,
   parent_locker = thd->m_statement_psi;
   thd->m_digest = NULL;
   thd->m_statement_psi = NULL;
-  bool rc = mysql_execute_command(thd);
+  bool rc = mysql_execute_command(thd, false, &last_time);
   thd->m_digest = parent_digest;
   DEBUG_SYNC(thd, "after_table_close");
   thd->m_statement_psi = parent_locker;