From 3f2f97d7731926aa830d3b39b8d0b96829e49e11 Mon Sep 17 00:00:00 2001 From: Francois Richard Date: Thu, 21 Mar 2019 16:12:05 -0700 Subject: [PATCH] FB8-128: track Semisync_ack Engine_commit time in slow query log (#982) (#982) Summary: Jira issue: https://jira.percona.com/browse/FB8-128 Reference Patch: https://github.com/facebook/mysql-5.6/commit/2dd16b3 Reference Pull: https://github.com/facebook/mysql-5.6/pull/681 Originally Reviewed By: lth Pull Request resolved: https://github.com/facebook/mysql-5.6/pull/982 Reviewed By: lloyd Differential Revision: D14421316 (https://github.com/facebook/mysql-5.6/commit/29729c9656685bd78063213d3ff9deb1b9a0059c) Pulled By: lth fbshipit-source-id: 8ec16de3049 --- mysql-test/r/slow_log_engine_fields.result | 4 ++++ mysql-test/t/slow_log_engine_fields-master.opt | 1 + mysql-test/t/slow_log_engine_fields.test | 16 ++++++++++++++++ sql/binlog.cc | 8 +++++++- sql/log.cc | 13 ++++++++++++- sql/sql_class.h | 4 ++++ 6 files changed, 44 insertions(+), 2 deletions(-) create mode 100644 mysql-test/r/slow_log_engine_fields.result create mode 100644 mysql-test/t/slow_log_engine_fields-master.opt create mode 100644 mysql-test/t/slow_log_engine_fields.test 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 d638d6be36ea..845e5f18c02d 100644 --- a/sql/binlog.cc +++ b/sql/binlog.cc @@ -9164,8 +9164,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 @@ -9182,7 +9186,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); mysql_mutex_unlock(&LOCK_commit); /* Process after_commit after LOCK_commit is released for avoiding diff --git a/sql/log.cc b/sql/log.cc index 7f96197f0873..3e229219fa15 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -758,7 +758,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, @@ -848,6 +848,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 ffbbe14e796d..3efe98a06f10 100644 --- a/sql/sql_class.h +++ b/sql/sql_class.h @@ -1330,6 +1330,10 @@ class THD : public MDL_context_owner, struct timeval start_time; struct timeval user_time; ulonglong start_utime, utime_after_lock; + /* 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