diff --git a/mysql-test/r/slow_log_engine_fields.result b/mysql-test/r/slow_log_engine_fields.result new file mode 100644 index 000000000000..90ef739e821e --- /dev/null +++ b/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 --git a/mysql-test/t/slow_log_engine_fields-master.opt b/mysql-test/t/slow_log_engine_fields-master.opt new file mode 100644 index 000000000000..8c5b1586810b --- /dev/null +++ b/mysql-test/t/slow_log_engine_fields-master.opt @@ -0,0 +1 @@ +--slow-query-log=1 --log-slow-extra=1 diff --git a/mysql-test/t/slow_log_engine_fields.test b/mysql-test/t/slow_log_engine_fields.test new file mode 100644 index 000000000000..29147ad1b34c --- /dev/null +++ b/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 --git a/sql/binlog.cc b/sql/binlog.cc index bca9545113cd..e78820ad6ac5 100644 --- a/sql/binlog.cc +++ b/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 --git a/sql/log.cc b/sql/log.cc index a0fa54b3412e..c3589912ebad 100644 --- a/sql/log.cc +++ b/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 --git a/sql/sql_class.h b/sql/sql_class.h index 1c12795b70c2..a1e8d64179f7 100644 --- a/sql/sql_class.h +++ b/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