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

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

Reference Patch: facebook/mysql-5.6@f2d6fdc

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

Test Plan: Jenkins.  All tests, including the new one, pass.

Reviewed By: yizhang82

Differential Revision: D14883715

Pulled By: yizhang82

fbshipit-source-id: 7e8f75d7d7b

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

@@ -177,6 +177,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.
 */
@@ -4727,7 +4730,9 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli,
           query_start_status = thd->status_var;
         }
 
-        mysql_parse(thd, &parser_state);
+        const ulonglong init_timer = my_timer_now();
+        ulonglong last_timer = init_timer;
+        mysql_parse(thd, &parser_state, &last_timer);
 
         enum_sql_command command = thd->lex->sql_command;
 
@@ -4774,6 +4779,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);
       }
 
@@ -9371,6 +9377,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 = nullptr;
   int error = 0;
+  ulonglong init_timer = my_timer_now();
 
   /*
     'thd' has been set by exec_relay_log_event(), just before calling
@@ -9941,6 +9948,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

@@ -8668,6 +8668,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,
@@ -8720,6 +8724,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),
@@ -8833,6 +8839,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

@@ -372,6 +372,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();
@@ -742,6 +745,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;
 
 /*

sql/sp_instr.cc

@@ -960,12 +960,14 @@ 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();
+
   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

@@ -1312,7 +1312,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"
@@ -135,6 +136,7 @@ bool mysql_open_cursor(THD *thd, Query_result *result,
             new (thd->mem_root) Query_result_materialize(result)))
     return true;
 
+  ulonglong last_time = my_timer_now();
   save_result = lex->result;
 
   lex->result = result_materialize;
@@ -143,7 +145,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;

sql/sql_parse.cc

@@ -1465,7 +1465,8 @@ static int process_noncurrent_db_rw(THD *thd, TABLE_LIST *all_tables) {
 static void check_secondary_engine_statement(THD *thd,
                                              Parser_state *parser_state,
                                              const char *query_string,
-                                             size_t query_length) {
+                                             size_t query_length,
+                                             ulonglong *last_timer) {
   // Only restart the statement if a non-fatal error was raised.
   if (!thd->is_error() || thd->is_killed() || thd->is_fatal_error()) return;
 
@@ -1517,12 +1518,12 @@ static void check_secondary_engine_statement(THD *thd,
   parser_state->reset(query_string, query_length);
 
   // Restart the statement.
-  mysql_parse(thd, parser_state);
+  mysql_parse(thd, parser_state, last_timer);
 
   // Check if the restarted statement failed, and if so, if it needs
   // another restart/fallback to the primary storage engine.
   check_secondary_engine_statement(thd, parser_state, query_string,
-                                   query_length);
+                                   query_length, last_timer);
 }
 
 static std::string perf_counter_factory_name() { return "simple"; }
@@ -1555,6 +1556,8 @@ bool dispatch_command(THD *thd, const COM_DATA *com_data,
   DBUG_PRINT("info", ("command: %d", command));
 
   Sql_cmd_clone *clone_cmd = nullptr;
+  const ulonglong init_timer = my_timer_now();
+  ulonglong last_timer = init_timer;
 
   /* For per-query performance counters with log_slow_statement */
   struct System_status_var query_start_status;
@@ -1867,12 +1870,12 @@ bool dispatch_command(THD *thd, const COM_DATA *com_data,
       thd->set_secondary_engine_optimization(
           Secondary_engine_optimization::PRIMARY_TENTATIVELY);
 
-      mysql_parse(thd, &parser_state);
+      mysql_parse(thd, &parser_state, &last_timer);
 
       // Check if the statement failed and needs to be restarted in
       // another storage engine.
       check_secondary_engine_statement(thd, &parser_state, orig_query.str,
-                                       orig_query.length);
+                                       orig_query.length, &last_timer);
 
       thd->set_secondary_engine_optimization(saved_secondary_engine);
 
@@ -1952,10 +1955,10 @@ bool dispatch_command(THD *thd, const COM_DATA *com_data,
         thd->set_secondary_engine_optimization(
             Secondary_engine_optimization::PRIMARY_TENTATIVELY);
         /* TODO: set thd->lex->sql_command to SQLCOM_END here */
-        mysql_parse(thd, &parser_state);
+        mysql_parse(thd, &parser_state, &last_timer);
 
-        check_secondary_engine_statement(thd, &parser_state,
-                                         beginning_of_next_stmt, length);
+        check_secondary_engine_statement(
+            thd, &parser_state, beginning_of_next_stmt, length, &last_timer);
 
         thd->set_secondary_engine_optimization(saved_secondary_engine);
       }
@@ -2314,6 +2317,11 @@ bool dispatch_command(THD *thd, const COM_DATA *com_data,
   thd->profiling->finish_current_query();
 #endif
 
+  /* Don't count the thread running on a master to send binlog events to a
+     slave as that runs a long time. */
+  if (command != COM_BINLOG_DUMP)
+    thd->status_var.command_time += my_timer_since(init_timer);
+
   DBUG_RETURN(error);
 }
 
@@ -2791,7 +2799,7 @@ static inline void binlog_gtid_end_transaction(THD *thd) {
     true        Error
 */
 
-int mysql_execute_command(THD *thd, bool first_level) {
+int mysql_execute_command(THD *thd, bool first_level, ulonglong *last_timer) {
   int res = false;
   LEX *const lex = thd->lex;
   /* first SELECT_LEX (have special meaning for many of non-SELECTcommands) */
@@ -4735,7 +4743,16 @@ int mysql_execute_command(THD *thd, bool first_level) {
     case SQLCOM_DROP_SRS:
 
       DBUG_ASSERT(lex->m_sql_cmd != nullptr);
+
+      /* The appropriate sql_cmd will set thd->pre_exec_time */
+      thd->pre_exec_time = 0;
       res = lex->m_sql_cmd->execute(thd);
+
+      if (last_timer && thd->pre_exec_time != 0) {
+        thd->status_var.pre_exec_time +=
+            my_timer_difftime(*last_timer, thd->pre_exec_time);
+        *last_timer = thd->pre_exec_time;
+      }
       break;
 
     case SQLCOM_ALTER_USER: {
@@ -4880,6 +4897,9 @@ int mysql_execute_command(THD *thd, bool first_level) {
     thd->query_plan.set_query_plan(SQLCOM_END, NULL, false);
   }
 
+  if (last_timer)
+    thd->status_var.exec_time += my_timer_since_and_update(last_timer);
+
   DBUG_ASSERT(!thd->in_active_multi_stmt_transaction() ||
               thd->in_multi_stmt_transaction_mode());
 
@@ -5424,7 +5444,7 @@ bool create_select_for_variable(Parse_context *pc, const char *var_name) {
   @param parser_state Parser state.
 */
 
-void mysql_parse(THD *thd, Parser_state *parser_state) {
+void mysql_parse(THD *thd, Parser_state *parser_state, ulonglong *last_timer) {
   DBUG_ENTER("mysql_parse");
   DBUG_PRINT("mysql_parse", ("query: '%s'", thd->query().str));
 
@@ -5490,6 +5510,9 @@ void mysql_parse(THD *thd, Parser_state *parser_state) {
     }
   }
 
+  if (last_timer)
+    thd->status_var.parse_time += my_timer_since_and_update(last_timer);
+
   if (!err) {
     thd->m_statement_psi = MYSQL_REFINE_STATEMENT(
         thd->m_statement_psi, sql_statement_info[thd->lex->sql_command].m_key);
@@ -5536,7 +5559,7 @@ void mysql_parse(THD *thd, Parser_state *parser_state) {
           bool switched = mgr_ptr->switch_resource_group_if_needed(
               thd, &src_res_grp, &dest_res_grp, &ticket, &cur_ticket);
 
-          error = mysql_execute_command(thd, true);
+          error = mysql_execute_command(thd, true, last_timer);
 
           if (switched)
             mgr_ptr->restore_original_resource_group(thd, src_res_grp,

sql/sql_parse.h

@@ -97,11 +97,13 @@ bool is_update_query(enum enum_sql_command command);
 bool is_explainable_query(enum enum_sql_command command);
 bool is_log_table_write_query(enum enum_sql_command command);
 bool alloc_query(THD *thd, const char *packet, size_t packet_length);
-void mysql_parse(THD *thd, Parser_state *parser_state);
+void mysql_parse(THD *thd, Parser_state *parser_state,
+                 ulonglong *last_timer = nullptr);
 void mysql_reset_thd_for_next_command(THD *thd);
 bool create_select_for_variable(Parse_context *pc, const char *var_name);
 void create_table_set_open_action_and_adjust_tables(LEX *lex);
-int mysql_execute_command(THD *thd, bool first_level = false);
+int mysql_execute_command(THD *thd, bool first_level = false,
+                          ulonglong *last_timer = nullptr);
 bool do_command(THD *thd);
 bool dispatch_command(THD *thd, const COM_DATA *com_data,
                       enum enum_server_command command);