FB8-128: track Semisync_ack Engine_commit time in slow query log (facebook#982) (facebook#982)

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

Reference Patch: facebook@2dd16b3
Reference Pull: facebook#681

Originally Reviewed By: lth
Pull Request resolved: facebook#982

Reviewed By: lloyd

Differential Revision: D14421316

Pulled By: lth

Author: Francois Richard

Diff for: mysql-test/r/slow_log_engine_fields.result

@@ -0,0 +1,4 @@
+SET SESSION long_query_time = 0;
+CREATE TABLE t1 (A INT);
+INSERT INTO t1 VALUES (1),(2),(3);
+DROP TABLE t1;

Diff for: mysql-test/t/slow_log_engine_fields-master.opt

@@ -0,0 +1 @@
+--slow-query-log=1 --log-slow-extra=1

Diff for: mysql-test/t/slow_log_engine_fields.test

@@ -0,0 +1,16 @@
+SET SESSION long_query_time = 0;
+
+CREATE TABLE t1 (A INT);
+INSERT INTO t1 VALUES (1),(2),(3);
+
+--let SEARCH_FILE = $MYSQLTEST_VARDIR/mysqld.1/mysqld-slow.log
+
+# Check if Semisync_ack_time is included in slow log results
+--let SEARCH_PATTERN= Semisync_ack_time:
+--source include/search_pattern_in_file.inc
+
+# Check if Engine_commit_time is included in slow log results
+--let SEARCH_PATTERN= Engine_commit_time:
+--source include/search_pattern_in_file.inc
+
+DROP TABLE t1;

Diff for: sql/binlog.cc

@@ -9507,8 +9507,12 @@ int MYSQL_BIN_LOG::ordered_commit(THD *thd, bool all, bool skip_commit) {
     DBUG_EXECUTE_IF("semi_sync_3-way_deadlock",
                     DEBUG_SYNC(thd, "before_process_commit_stage_queue"););
 
-    if (flush_error == 0 && sync_error == 0)
+    ulonglong start_time;
+    if (flush_error == 0 && sync_error == 0) {
+      start_time = my_timer_now();
       sync_error = call_after_sync_hook(commit_queue);
+      thd->semisync_ack_time = my_timer_since(start_time);
+    }
 
     /*
       process_commit_stage_queue will call update_on_commit or
@@ -9525,7 +9529,9 @@ int MYSQL_BIN_LOG::ordered_commit(THD *thd, bool all, bool skip_commit) {
       Gtid_set, and adding and removing intervals requires a mutex,
       which would reduce performance.
     */
+    start_time = my_timer_now();
     process_commit_stage_queue(thd, commit_queue);
+    thd->engine_commit_time = my_timer_since(start_time);
 
     /**
      * After commit stage

Diff for: sql/log.cc

@@ -775,7 +775,7 @@ bool File_query_log::write_slow(THD *thd, ulonglong current_utime,
         " Sort_rows: %lu Sort_scan_count: %lu"
         " Created_tmp_disk_tables: %lu"
         " Created_tmp_tables: %lu"
-        " Start: %s End: %s\n";
+        " Start: %s End: %s";
 
     // If the query start status is valid - i.e. the current thread's
     // status values should be no less than the query start status,
@@ -884,6 +884,17 @@ bool File_query_log::write_slow(THD *thd, ulonglong current_utime,
           end_time_buff);
     }
     if (error == (uint)-1) goto err;
+
+    static const char *times =
+        " Semisync_ack_time: %s Engine_commit_time: %s\n";
+    /* Semisync ack time and Engine commit time  */
+    sprintf(query_time_buff, "%.6f",
+            my_timer_to_seconds(thd->semisync_ack_time));
+    sprintf(lock_time_buff, "%.6f",
+            my_timer_to_seconds(thd->engine_commit_time));
+    if (my_b_printf(&log_file, times, query_time_buff, lock_time_buff) ==
+        (uint)-1)
+      goto err;
   }
 
   if (thd->db().str && strcmp(thd->db().str, db)) {  // Database changed

Diff for: sql/sql_class.h

@@ -1604,6 +1604,10 @@ class THD : public MDL_context_owner,
     m_lock_usec = 0;
   }
   void pop_lock_usec(ulonglong top) { m_lock_usec = top; }
+  /* record the semisync ack time */
+  ulonglong semisync_ack_time = 0;
+  /* record the engine commit time */
+  ulonglong engine_commit_time = 0;
 
   /**
     Type of lock to be used for all DML statements, except INSERT, in cases