[mysql-5.6][PR] track Semisync_ack Engine_commit time in slow query log

Summary: Closes facebook#681 GitHub Author: Francois Richard <[email protected]> Github PR Sync: {sync, type="child", parent="github", parentrepo="facebook/mysql-5.6", parentprnum="681", parentprfbid="1959343724341677"} Test Plan: Imported from GitHub, without a `Test Plan:` line. Reviewers: mung Reviewed By: mung Subscribers: yoshinori, phabricatorlinter, [email protected] Differential Revision: https://phabricator.intern.facebook.com/D5625496 Signature: t1:5625496:1502906705:f1473626a3431a275726a2ff0f42c6ea7895680a
inikep · Aug 24, 2017 · e74d0cc · e74d0cc
1 parent ee05d9a
commit e74d0cc
Show file tree

Hide file tree

Showing 9 changed files with 52 additions and 4 deletions.
diff --git a/mysql-test/r/slow_log_engine_commit_time.result b/mysql-test/r/slow_log_engine_commit_time.result
@@ -0,0 +1,4 @@
+set timestamp=10;
+select unix_timestamp(), sleep(2);
+unix_timestamp()	sleep(2)
+10	0
diff --git a/mysql-test/r/slow_log_semisync_ack_time.result b/mysql-test/r/slow_log_semisync_ack_time.result
@@ -0,0 +1,4 @@
+set timestamp=10;
+select unix_timestamp(), sleep(2);
+unix_timestamp()	sleep(2)
+10	0
diff --git a/mysql-test/t/slow_log_engine_commit_time-master.opt b/mysql-test/t/slow_log_engine_commit_time-master.opt
@@ -0,0 +1 @@
+--slow-query-log=1 --long-query-time=1 --log-slow-extra=1
diff --git a/mysql-test/t/slow_log_engine_commit_time.test b/mysql-test/t/slow_log_engine_commit_time.test
@@ -0,0 +1,7 @@
+set timestamp=10;
+select unix_timestamp(), sleep(2);
+
+let $MYSQLD_DATADIR= `select @@datadir`;
+--exec [ `grep "Engine_commit_time:" $MYSQLD_DATADIR/../mysqld-slow.log | wc -l` -ge "1" ]
+
+--exit
diff --git a/mysql-test/t/slow_log_semisync_ack_time-master.opt b/mysql-test/t/slow_log_semisync_ack_time-master.opt
@@ -0,0 +1 @@
+--slow-query-log=1 --long-query-time=1 --log-slow-extra=1
diff --git a/mysql-test/t/slow_log_semisync_ack_time.test b/mysql-test/t/slow_log_semisync_ack_time.test
@@ -0,0 +1,7 @@
+set timestamp=10;
+select unix_timestamp(), sleep(2);
+
+let $MYSQLD_DATADIR= `select @@datadir`;
+--exec [ `grep "Semisync_ack_time:" $MYSQLD_DATADIR/../mysqld-slow.log | wc -l` -ge "1" ]
+
+--exit
diff --git a/sql/binlog.cc b/sql/binlog.cc
@@ -7997,7 +7997,11 @@ int MYSQL_BIN_LOG::ordered_commit(THD *thd, bool all, bool skip_commit,
   }
   semisync_queue =
     stage_manager.fetch_queue_for(Stage_manager::SEMISYNC_STAGE);
+
+  ulonglong start_time;
+  start_time = my_timer_now();
   process_semisync_stage_queue(semisync_queue);
+  thd->semisync_ack_time = my_timer_since(start_time);
 
   leave_mutex_before_commit_stage= &LOCK_semisync;
 
@@ -8026,7 +8030,9 @@ int MYSQL_BIN_LOG::ordered_commit(THD *thd, bool all, bool skip_commit,
       DBUG_RETURN(finish_commit(thd, async));
     }
     THD *commit_queue= stage_manager.fetch_queue_for(Stage_manager::COMMIT_STAGE);
+    start_time = my_timer_now();
     process_commit_stage_queue(thd, commit_queue, async);
+    thd->engine_commit_time = my_timer_since(start_time);
     mysql_mutex_unlock(&LOCK_commit);
     final_queue= commit_queue;
   }

diff --git a/sql/log.cc b/sql/log.cc
@@ -2108,6 +2108,8 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
   char start_time_buff[80] = "";
   char end_time_buff[80] = "";
   char read_time_buff[80] = "";
+  char semisync_ack_time_buff[80] = "";
+  char engine_commit_time_buff[80] = "";
   char query_time_buff[22+7], lock_time_buff[22+7];
   bool use_query_start = false;
   uint buff_len= 0;
@@ -2163,6 +2165,12 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
   /* For slow query log */
   sprintf(query_time_buff, "%.6f", ulonglong2double(query_utime)/1000000.0);
   sprintf(lock_time_buff,  "%.6f", ulonglong2double(lock_utime)/1000000.0);
+  /*Semisync ack time and Engine commit time  */
+  sprintf(semisync_ack_time_buff,"%.6f",
+          my_timer_to_seconds(thd->semisync_ack_time));
+  sprintf(engine_commit_time_buff,"%.6f",
+          my_timer_to_seconds(thd->engine_commit_time));
+
   if (opt_log_slow_extra && query_start_arg && query_start)
   {
     struct tm tm_tmp;
@@ -2236,7 +2244,8 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
                       " Created_tmp_tables: %lu"
                       " Tmp_table_bytes_written: %lu"
                       " Start: %s End: %s"
-                      " Reads: %lu Read_time: %s\n",
+                      " Reads: %lu Read_time: %s"
+                      " Semisync_ack_time: %s Engine_commit_time: %s\n",
                       query_time_buff, lock_time_buff,
                       (ulong) thd->get_sent_row_count(),
                       (ulong) thd->get_examined_row_count(),
@@ -2282,7 +2291,9 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
                       start_time_buff, end_time_buff,
                       (ulong) (thd->status_var.read_requests -
                           query_start->read_requests),
-                      read_time_buff) == (uint) -1)
+                      read_time_buff,
+                      semisync_ack_time_buff,
+                      engine_commit_time_buff) == (uint) -1)
       tmp_errno=errno;
     }
     else // don't substract query_start status
@@ -2302,7 +2313,8 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
                       " Created_tmp_tables: %lu"
                       " Tmp_table_bytes_written: %lu"
                       " Start: %s End: %s"
-                      " Reads: %lu Read_time: %s\n",
+                      " Reads: %lu Read_time: %s"
+                      " Semisync_ack_time: %s Engine_commit_time: %s\n",
                       query_time_buff, lock_time_buff,
                       (ulong) thd->get_sent_row_count(),
                       (ulong) thd->get_examined_row_count(),
@@ -2329,7 +2341,9 @@ bool MYSQL_QUERY_LOG::write(THD *thd, time_t current_time,
                       (ulong) thd->status_var.tmp_table_bytes_written,
                       start_time_buff, end_time_buff,
                       (ulong) thd->status_var.read_requests,
-                      read_time_buff) == (uint) -1)
+                      read_time_buff,
+                      semisync_ack_time_buff,
+                      engine_commit_time_buff) == (uint) -1)
       tmp_errno=errno;
     }
 

diff --git a/sql/sql_class.h b/sql/sql_class.h
@@ -2449,6 +2449,10 @@ class THD :public MDL_context_owner,
   ulonglong stmt_start = 0;
   /* record the transaction time (including in-fly) */
   ulonglong trx_time = 0;
+  /* record the semisync ack time */
+  ulonglong semisync_ack_time = 0;
+  /* record the engine commit time */
+  ulonglong engine_commit_time = 0;
 
   /* whether the session is already in admission control for queries */
   bool is_in_ac = false;
Original file line number	Diff line number	Diff line change
		@@ -0,0 +1 @@
		--slow-query-log=1 --long-query-time=1 --log-slow-extra=1