Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
wants to merge 1 commit into from
Closed

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions mysql-test/r/slow_log_engine_fields.result
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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;
1 change: 1 addition & 0 deletions mysql-test/t/slow_log_engine_fields-master.opt
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
--slow-query-log=1 --log-slow-extra=1
16 changes: 16 additions & 0 deletions mysql-test/t/slow_log_engine_fields.test
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can there be a pre-existing slow log, resulting in false positives?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This feature is compiled inside a server so all comments in slow log should have "Semisync_ack_time" or none. For this case "--repeat" doesn't matter.


# 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;
8 changes: 7 additions & 1 deletion sql/binlog.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8716,8 +8716,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
Expand All @@ -8734,7 +8738,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
Expand Down
13 changes: 12 additions & 1 deletion sql/log.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -745,7 +745,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,
Expand Down Expand Up @@ -831,6 +831,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
if (my_b_printf(&log_file, "use %s;\n", thd->db().str) == (uint)-1)
Expand Down
4 changes: 4 additions & 0 deletions sql/sql_class.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1263,6 +1263,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
Expand Down