From 3dc7526ea386f950359d7a4d2e67e69478927dab Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jean-Fran=C3=A7ois=20Gagn=C3=A9?= <8471576+jfg956@users.noreply.github.com> Date: Wed, 10 Jul 2024 18:09:30 -0400 Subject: [PATCH] Implement Bug#106645: Slow query log is not logging database/schema name. Bug#106645: https://bugs.mysql.com/bug.php?id=106645 --- .../include/slow_query_log_file_reset.inc | 8 ++ .../sys_vars/r/log_slow_extra_db_basic.result | 87 ++++++++++++++ .../sys_vars/r/log_slow_extra_db_func.result | 62 ++++++++++ .../sys_vars/r/log_slow_extra_func.result | 48 ++++++++ .../sys_vars/t/log_slow_extra_db_basic.test | 86 ++++++++++++++ .../sys_vars/t/log_slow_extra_db_func.test | 109 ++++++++++++++++++ .../suite/sys_vars/t/log_slow_extra_func.test | 82 +++++++++++++ sql/log.cc | 65 +++++++++-- sql/mysqld.cc | 1 + sql/mysqld.h | 1 + sql/sys_vars.cc | 16 +++ 11 files changed, 555 insertions(+), 10 deletions(-) create mode 100644 mysql-test/include/slow_query_log_file_reset.inc create mode 100644 mysql-test/suite/sys_vars/r/log_slow_extra_db_basic.result create mode 100644 mysql-test/suite/sys_vars/r/log_slow_extra_db_func.result create mode 100644 mysql-test/suite/sys_vars/r/log_slow_extra_func.result create mode 100644 mysql-test/suite/sys_vars/t/log_slow_extra_db_basic.test create mode 100644 mysql-test/suite/sys_vars/t/log_slow_extra_db_func.test create mode 100644 mysql-test/suite/sys_vars/t/log_slow_extra_func.test diff --git a/mysql-test/include/slow_query_log_file_reset.inc b/mysql-test/include/slow_query_log_file_reset.inc new file mode 100644 index 000000000000..763973ad3bfc --- /dev/null +++ b/mysql-test/include/slow_query_log_file_reset.inc @@ -0,0 +1,8 @@ + +let $_INTERNAL_MYSQLD_DATADIR = `select @@datadir`; +let $_INTERNAL_MYSQLD_SLOW_QUERY_LOG_FILE = `select @@slow_query_log_file`; + +--echo +--echo ## Resetting the slow query log file. +--remove_file $MYSQLD_DATADIR/$_INTERNAL_MYSQLD_SLOW_QUERY_LOG_FILE +FLUSH SLOW LOGS; diff --git a/mysql-test/suite/sys_vars/r/log_slow_extra_db_basic.result b/mysql-test/suite/sys_vars/r/log_slow_extra_db_basic.result new file mode 100644 index 000000000000..3c25fa16db1d --- /dev/null +++ b/mysql-test/suite/sys_vars/r/log_slow_extra_db_basic.result @@ -0,0 +1,87 @@ +# Bug#106645: Slow query log is not logging database/schema name. + +# test global variable "log_slow_extra_db" + +SELECT @@global.log_slow_extra_db INTO @old_lsed; +SELECT @@global.log_output INTO @old_lo; +SELECT @@global.slow_query_log INTO @old_sql; +# invalid values / types +SET GLOBAL log_slow_extra_db=symbol; +ERROR 42000: Variable 'log_slow_extra_db' can't be set to the value of 'symbol' +SET GLOBAL log_slow_extra_db="string"; +ERROR 42000: Variable 'log_slow_extra_db' can't be set to the value of 'string' +SET GLOBAL log_slow_extra_db=99; +ERROR 42000: Variable 'log_slow_extra_db' can't be set to the value of '99' +SET GLOBAL log_slow_extra_db=0.5; +ERROR 42000: Incorrect argument type to variable 'log_slow_extra_db' + +# only GLOBAL scope is valid +SET SESSION log_slow_extra_db=0; +ERROR HY000: Variable 'log_slow_extra_db' is a GLOBAL variable and should be set with SET GLOBAL + +# valid values +SET GLOBAL slow_query_log=0; +SET GLOBAL log_slow_extra_db=0; +SELECT @@global.log_slow_extra_db; +@@global.log_slow_extra_db +0 +SET GLOBAL log_slow_extra_db=1; +SELECT @@global.log_slow_extra_db; +@@global.log_slow_extra_db +1 +SET GLOBAL log_slow_extra_db=OFF; +SELECT @@global.log_slow_extra_db; +@@global.log_slow_extra_db +0 +SET GLOBAL log_slow_extra_db=ON; +SELECT @@global.log_slow_extra_db; +@@global.log_slow_extra_db +1 +SET GLOBAL log_slow_extra_db=DEFAULT; +SELECT @@global.log_slow_extra_db; +@@global.log_slow_extra_db +1 + +# warnings and errors +SET GLOBAL slow_query_log=1; + +# Switching slow query log file format while target is not FILE is legal, +# but does nothing. Throw a warning! +SET GLOBAL log_output="TABLE"; +SELECT @@global.log_slow_extra_db INTO @old; +SET GLOBAL log_slow_extra_db=0; +Warnings: +Warning 3795 slow query log file format changed as requested, but setting will have no effect when not actually logging to a file. +# Value must have changed: +SELECT @@global.log_slow_extra_db!=@old; +@@global.log_slow_extra_db!=@old +1 +SET GLOBAL log_slow_extra_db=DEFAULT; +Warnings: +Warning 3795 slow query log file format changed as requested, but setting will have no effect when not actually logging to a file. + +# Switching slow query log file format while target is not FILE is legal, +# but does nothing. Throw a warning! +SET GLOBAL log_output="NONE"; +SELECT @@global.log_slow_extra_db INTO @old; +SET GLOBAL log_slow_extra_db=0; +Warnings: +Warning 3795 slow query log file format changed as requested, but setting will have no effect when not actually logging to a file. +# Value must have changed: +SELECT @@global.log_slow_extra_db!=@old; +@@global.log_slow_extra_db!=@old +1 +SET GLOBAL log_slow_extra_db=DEFAULT; +Warnings: +Warning 3795 slow query log file format changed as requested, but setting will have no effect when not actually logging to a file. + +# clean up +SET GLOBAL log_slow_extra_db=@old_lsed; +Warnings: +Warning 3795 slow query log file format changed as requested, but setting will have no effect when not actually logging to a file. +SET GLOBAL log_output=@old_lo; +SET GLOBAL slow_query_log=@old_sql; +TRUNCATE TABLE mysql.general_log; +TRUNCATE TABLE mysql.slow_log; + +# READY diff --git a/mysql-test/suite/sys_vars/r/log_slow_extra_db_func.result b/mysql-test/suite/sys_vars/r/log_slow_extra_db_func.result new file mode 100644 index 000000000000..1195feb92502 --- /dev/null +++ b/mysql-test/suite/sys_vars/r/log_slow_extra_db_func.result @@ -0,0 +1,62 @@ +# Bug#106645: Slow query log is not logging database/schema name. + +## Save state. +SET @global_log_output = @@global.log_output; +SET @global_slow_query_log = @@global.slow_query_log; +SET @global_slow_query_log_file = @@global.slow_query_log_file; +SET @global_log_slow_extra = @@global.log_slow_extra; +SET @global_log_slow_extra_db = @@global.log_slow_extra_db; + +## Common to all tests below. +SET @@global.slow_query_log_file = 'my_slow_test.log'; +SET @@global.log_output = 'FILE'; +SET @@global.slow_query_log = ON; +SET @@global.log_slow_extra = 0; +SET @@session.long_query_time = 0.1; + +## Resetting the slow query log file. +FLUSH SLOW LOGS; + +SET @@global.log_slow_extra_db = 1; +SELECT sleep(0.5); +sleep(0.5) +0 + +# Time: x +# UH: n Id: n Db: test +# Query_time: n Lock_time: n Rows_sent: 1 Rows_examined: 1 +SELECT sleep(0.5); + +## Resetting the slow query log file. +FLUSH SLOW LOGS; + +SET @@session.long_query_time = 0.1; +SELECT sleep(0.5); +sleep(0.5) +0 + +# Time: x +# UH: n Id: n Db: +# Query_time: n Lock_time: n Rows_sent: 1 Rows_examined: 1 +SELECT sleep(0.5); + +## Resetting the slow query log file. +FLUSH SLOW LOGS; + +SET @@global.log_slow_extra_db = 0; +SELECT sleep(0.5); +sleep(0.5) +0 + +# Time: x +# UH: n Id: n +# Query_time: n Lock_time: n Rows_sent: 1 Rows_examined: 1 +use test; +SELECT sleep(0.5); + +## Restore state. +SET @@global.log_slow_extra = @global_log_slow_extra; +SET @@global.log_slow_extra_db = @global_log_slow_extra_db; +SET @@global.log_output = @global_log_output; +SET @@global.slow_query_log = @global_slow_query_log; +SET @@global.slow_query_log_file = @global_slow_query_log_file; diff --git a/mysql-test/suite/sys_vars/r/log_slow_extra_func.result b/mysql-test/suite/sys_vars/r/log_slow_extra_func.result new file mode 100644 index 000000000000..06f19e025d10 --- /dev/null +++ b/mysql-test/suite/sys_vars/r/log_slow_extra_func.result @@ -0,0 +1,48 @@ +# WL#12393: Logging: Add new command line option for richer slow query logging + +## Save state. +SET @global_log_output = @@global.log_output; +SET @global_slow_query_log = @@global.slow_query_log; +SET @global_slow_query_log_file = @@global.slow_query_log_file; +SET @global_log_slow_extra = @@global.log_slow_extra; +SET @global_log_slow_extra_db = @@global.log_slow_extra_db; + +## Common to all tests below. +SET @@global.slow_query_log_file = 'my_slow_test.log'; +SET @@global.log_output = 'FILE'; +SET @@global.slow_query_log = ON; +SET @@global.log_slow_extra_db = 1; +SET @@session.long_query_time = 0.1; + +## Resetting the slow query log file. +FLUSH SLOW LOGS; + +SET @@global.log_slow_extra = 0; +SELECT sleep(0.5); +sleep(0.5) +0 + +# Time: x +# User@Host: n Id: n Db: test +# Query_time: n Lock_time: n Rows_sent: 1 Rows_examined: 1 +SELECT sleep(0.5); + +## Resetting the slow query log file. +FLUSH SLOW LOGS; + +SET @@global.log_slow_extra = 1; +SELECT sleep(0.5); +sleep(0.5) +0 + +# Time: x +# User@Host: n Id: n Db: test +# Query_time: n Lock_time: n Rows_sent: 1 Rows_examined: 1 Thread_id: n Errno: 0 Killed: 0 Bytes_received: n Bytes_sent: n Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: n End: n +SELECT sleep(0.5); + +## Restore state. +SET @@global.log_slow_extra = @global_log_slow_extra; +SET @@global.log_slow_extra_db = @global_log_slow_extra_db; +SET @@global.log_output = @global_log_output; +SET @@global.slow_query_log = @global_slow_query_log; +SET @@global.slow_query_log_file = @global_slow_query_log_file; diff --git a/mysql-test/suite/sys_vars/t/log_slow_extra_db_basic.test b/mysql-test/suite/sys_vars/t/log_slow_extra_db_basic.test new file mode 100644 index 000000000000..bc4687f70dee --- /dev/null +++ b/mysql-test/suite/sys_vars/t/log_slow_extra_db_basic.test @@ -0,0 +1,86 @@ +--echo # Bug#106645: Slow query log is not logging database/schema name. +--echo +--echo # test global variable "log_slow_extra_db" +--echo + +SELECT @@global.log_slow_extra_db INTO @old_lsed; +SELECT @@global.log_output INTO @old_lo; +SELECT @@global.slow_query_log INTO @old_sql; + +--echo # invalid values / types + +--error ER_WRONG_VALUE_FOR_VAR +SET GLOBAL log_slow_extra_db=symbol; + +--error ER_WRONG_VALUE_FOR_VAR +SET GLOBAL log_slow_extra_db="string"; + +--error ER_WRONG_VALUE_FOR_VAR +SET GLOBAL log_slow_extra_db=99; + +--error ER_WRONG_TYPE_FOR_VAR +SET GLOBAL log_slow_extra_db=0.5; + +--echo +--echo # only GLOBAL scope is valid + +--error ER_GLOBAL_VARIABLE +SET SESSION log_slow_extra_db=0; + +--echo + +--echo # valid values +SET GLOBAL slow_query_log=0; + +SET GLOBAL log_slow_extra_db=0; +SELECT @@global.log_slow_extra_db; + +SET GLOBAL log_slow_extra_db=1; +SELECT @@global.log_slow_extra_db; + +SET GLOBAL log_slow_extra_db=OFF; +SELECT @@global.log_slow_extra_db; + +SET GLOBAL log_slow_extra_db=ON; +SELECT @@global.log_slow_extra_db; + +SET GLOBAL log_slow_extra_db=DEFAULT; +SELECT @@global.log_slow_extra_db; + +--echo + +--echo # warnings and errors + +SET GLOBAL slow_query_log=1; +--echo + +--echo # Switching slow query log file format while target is not FILE is legal, +--echo # but does nothing. Throw a warning! +SET GLOBAL log_output="TABLE"; +SELECT @@global.log_slow_extra_db INTO @old; +SET GLOBAL log_slow_extra_db=0; +--echo # Value must have changed: +SELECT @@global.log_slow_extra_db!=@old; +SET GLOBAL log_slow_extra_db=DEFAULT; +--echo + +--echo # Switching slow query log file format while target is not FILE is legal, +--echo # but does nothing. Throw a warning! +SET GLOBAL log_output="NONE"; +SELECT @@global.log_slow_extra_db INTO @old; +SET GLOBAL log_slow_extra_db=0; +--echo # Value must have changed: +SELECT @@global.log_slow_extra_db!=@old; +SET GLOBAL log_slow_extra_db=DEFAULT; +--echo + +--echo # clean up +SET GLOBAL log_slow_extra_db=@old_lsed; +SET GLOBAL log_output=@old_lo; +SET GLOBAL slow_query_log=@old_sql; +TRUNCATE TABLE mysql.general_log; +TRUNCATE TABLE mysql.slow_log; + +--echo + +--echo # READY diff --git a/mysql-test/suite/sys_vars/t/log_slow_extra_db_func.test b/mysql-test/suite/sys_vars/t/log_slow_extra_db_func.test new file mode 100644 index 000000000000..282005dc093d --- /dev/null +++ b/mysql-test/suite/sys_vars/t/log_slow_extra_db_func.test @@ -0,0 +1,109 @@ +--echo # Bug#106645: Slow query log is not logging database/schema name. +--echo + +# Common variables for all tests. + +--let $MYSQLD_DATADIR= `select @@datadir` + +# These regex patterns are for masking-out non-deterministic output. +--let $PATTERN_VER= /.*Version.*started with.*\n// +--let $PATTERN_TCP= /^Tcp port:.*Unix socket:.*\n// +--let $PATTERN_TIME1= /^Time.*Id.*Command.*Argument.*\n// +--let $PATTERN_TIME2= /^# Time: .*/# Time: x/ + +# Replacing User@Host by UH as a trick to conserve "Db: ..." when it is there. +--let $PATTERN_UH1= /^# User@Host:.*Id:.*Db:/# UH: n Id: n Db:/ +--let $PATTERN_UH2= /^# User@Host:.*Id:.*/# UH: n Id: n/ + +--let $PATTERN_QT= /^# Query_time: .*Lock_time: .*Rows_sent:/# Query_time: n Lock_time: n Rows_sent:/ +--let $PATTERN_TS= /SET timestamp=.*\n// + +--let $PATTERN= $PATTERN_VER $PATTERN_TCP $PATTERN_TIME1 $PATTERN_TIME2 $PATTERN_UH1 $PATTERN_UH2 $PATTERN_QT $PATTERN_TS + +--echo ## Save state. +SET @global_log_output = @@global.log_output; +SET @global_slow_query_log = @@global.slow_query_log; +SET @global_slow_query_log_file = @@global.slow_query_log_file; +SET @global_log_slow_extra = @@global.log_slow_extra; +SET @global_log_slow_extra_db = @@global.log_slow_extra_db; + +--echo +--echo ## Common to all tests below. + +# Setting slow_query_log_file before enabling the slow log to avoid creating a random file. +SET @@global.slow_query_log_file = 'my_slow_test.log'; + +SET @@global.log_output = 'FILE'; +SET @@global.slow_query_log = ON; + +# This needs to go after log_output as it might warn otherwise. +SET @@global.log_slow_extra = 0; + +SET @@session.long_query_time = 0.1; + +# We test log_slow_extra_db = 1 before 0 as we want to make sure a "use ..." appears with 0. + +# Clean slow query log file before test. +--source include/slow_query_log_file_reset.inc + +--echo +SET @@global.log_slow_extra_db = 1; +SELECT sleep(0.5); + +--echo +# Checking the content of the slow query log file. +--replace_regex $PATTERN +--exec cat $MYSQLD_DATADIR/my_slow_test.log + +# New connection with no selected database. +# Below from the doc... +# https://dev.mysql.com/doc/dev/mysql-server/latest/PAGE_MYSQL_TEST_COMMANDS.html +# connect (name, host_name, user_name, password, db_name [,port_num ... +# *NO-ONE* means that no default database should be selected +--connect(conn1,localhost,root,,*NO-ONE*) +connection conn1; + +# Clean slow query log file before test. +--source include/slow_query_log_file_reset.inc + +--echo +SET @@session.long_query_time = 0.1; +SELECT sleep(0.5); + +--echo +# Checking the content of the slow query log file. +--replace_regex $PATTERN +--exec cat $MYSQLD_DATADIR/my_slow_test.log + +# Setting back connection to default, and cleanup. +connection default; +disconnect conn1; + +# As we tested with 1 before, we expect a "use ..." to appear with 0. + +# Clean slow query log file before test. +--source include/slow_query_log_file_reset.inc + +--echo +SET @@global.log_slow_extra_db = 0; +SELECT sleep(0.5); + +--echo +# Checking the content of the slow query log file. +--replace_regex $PATTERN +--exec cat $MYSQLD_DATADIR/my_slow_test.log + +# Cleanup. +--remove_file $MYSQLD_DATADIR/my_slow_test.log + +--echo +--echo ## Restore state. +# These need to go before log_output as they might warn otherwise. +SET @@global.log_slow_extra = @global_log_slow_extra; +SET @@global.log_slow_extra_db = @global_log_slow_extra_db; + +SET @@global.log_output = @global_log_output; +SET @@global.slow_query_log = @global_slow_query_log; +SET @@global.slow_query_log_file = @global_slow_query_log_file; + +# EOF. \ No newline at end of file diff --git a/mysql-test/suite/sys_vars/t/log_slow_extra_func.test b/mysql-test/suite/sys_vars/t/log_slow_extra_func.test new file mode 100644 index 000000000000..7ad36c710b38 --- /dev/null +++ b/mysql-test/suite/sys_vars/t/log_slow_extra_func.test @@ -0,0 +1,82 @@ +# This is contributed with Bug#106645, but this still is about WL#12393. +--echo # WL#12393: Logging: Add new command line option for richer slow query logging +--echo + +# Common variables for all tests. + +let $MYSQLD_DATADIR= `select @@datadir`; + +# These regex patterns are for masking-out non-deterministic output. +--let $PATTERN_VER= /.*Version.*started with.*\n// +--let $PATTERN_TCP= /^Tcp port:.*Unix socket:.*\n// +--let $PATTERN_TIME1= /^Time.*Id.*Command.*Argument.*\n// +--let $PATTERN_TIME2= /^# Time: .*/# Time: x/ +--let $PATTERN_UH= /^# User@Host:.*Id:.*Db:/# User@Host: n Id: n Db:/ +--let $PATTERN_QT= /^# Query_time: .*Lock_time: .*Rows_sent:/# Query_time: n Lock_time: n Rows_sent:/ +--let $PATTERN_THREAD= /Thread_id:.*Errno:/Thread_id: n Errno:/ +--let $PATTERN_BR= /Bytes_received:.*Bytes_sent:.*Read_first:/Bytes_received: n Bytes_sent: n Read_first:/ +--let $PATTERN_START= /Start:.*End:.*/Start: n End: n/ +--let $PATTERN_TS= /SET timestamp=.*\n// + +--let $PATTERN= $PATTERN_VER $PATTERN_TCP $PATTERN_TIME1 $PATTERN_TIME2 $PATTERN_UH $PATTERN_QT $PATTERN_THREAD $PATTERN_BR $PATTERN_START $PATTERN_TS + +--echo ## Save state. +SET @global_log_output = @@global.log_output; +SET @global_slow_query_log = @@global.slow_query_log; +SET @global_slow_query_log_file = @@global.slow_query_log_file; +SET @global_log_slow_extra = @@global.log_slow_extra; +SET @global_log_slow_extra_db = @@global.log_slow_extra_db; + +--echo +--echo ## Common to all tests below. + +# Setting slow_query_log_file before enabling the slow log to avoid creating a random file. +SET @@global.slow_query_log_file = 'my_slow_test.log'; + +SET @@global.log_output = 'FILE'; +SET @@global.slow_query_log = ON; + +# This needs to go after log_output as it might warn otherwise. +# Doing tests with log_slow_extra_db = 1 allows not having to manage "use ..." in the output. +SET @@global.log_slow_extra_db = 1; + +SET @@session.long_query_time = 0.1; + +# Clean slow query log file before test. +--source include/slow_query_log_file_reset.inc + +--echo +SET @@global.log_slow_extra = 0; +SELECT sleep(0.5); + +--echo +# Checking the content of the slow query log file. +--replace_regex $PATTERN +--exec cat $MYSQLD_DATADIR/my_slow_test.log + +# Clean slow query log file before test. +--source include/slow_query_log_file_reset.inc + +--echo +SET @@global.log_slow_extra = 1; +SELECT sleep(0.5); + +--echo +# Checking the content of the slow query log file. +--replace_regex $PATTERN +--exec cat $MYSQLD_DATADIR/my_slow_test.log + +# Cleanup. +--remove_file $MYSQLD_DATADIR/my_slow_test.log + +--echo +--echo ## Restore state. +# These need to go before log_output as they might warn otherwise. +SET @@global.log_slow_extra = @global_log_slow_extra; +SET @@global.log_slow_extra_db = @global_log_slow_extra_db; + +SET @@global.log_output = @global_log_output; +SET @@global.slow_query_log = @global_slow_query_log; +SET @@global.slow_query_log_file = @global_slow_query_log_file; + +# EOF. \ No newline at end of file diff --git a/sql/log.cc b/sql/log.cc index bcfd73a25a57..4fe888446385 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -693,27 +693,58 @@ bool File_query_log::write_slow(THD *thd, ulonglong current_utime, size_t sql_text_len) { char buff[80], *end; char query_time_buff[22 + 7], lock_time_buff[22 + 7]; - size_t buff_len; - end = buff; + + /* In my patch for Bug#106645, I am allowing myself to change the initial assignment of end + * from buff to NULL and assigning it to buff when it is used. IMHO it makes clearer + * that there are many independent usages of buff in this function, + * but feel free to revert if you do not like it. */ + /* Will be set to buff below, but setting to NULL now to make clear when this is used. + * Cannot declare when used as "goto err" would cross a declaration / initialization boundary. */ + end = NULL; mysql_mutex_lock(&LOCK_log); assert(is_open()); + /* For only logging db changes when db is not in the comment line. + * With SPECIAL_SHORT_LOG_FORMAT, always log db changes because no comment line. */ + bool log_db_change = true; + if (!(specialflag & SPECIAL_SHORT_LOG_FORMAT)) { char my_timestamp[iso8601_size]; make_iso8601_timestamp(my_timestamp, current_utime, iso8601_sysvar_logtimestamps); - buff_len = snprintf(buff, sizeof buff, "# Time: %s\n", my_timestamp); + /* In my patch for Bug#106645, I am allowing myself to inline the declaration of buff_len. + * IMHO, this makes things better as after removing the usage of buff_len further down below, + * here is the only place where it is used, but feel free to revert if you do not like it. */ + size_t buff_len = snprintf(buff, sizeof buff, "# Time: %s\n", my_timestamp); /* Note that my_b_write() assumes it knows the length for this */ if (my_b_write(&log_file, (uchar *)buff, buff_len)) goto err; - buff_len = snprintf(buff, 32, "%5u", thd->thread_id()); - if (my_b_printf(&log_file, "# User@Host: %s Id: %s\n", user_host, buff) == - (uint)-1) - goto err; + if (!opt_log_slow_extra_db) { + /* This section of code will eventually be removed when everyone will be used + * to the new slow query log file format with "Db:". */ + snprintf(buff, 32, "%5u", thd->thread_id()); + if (my_b_printf(&log_file, "# User@Host: %s Id: %s\n", user_host, buff) == (uint)-1) + goto err; + } else { + log_db_change = false; + db[0] = 0; /* Resetting db triggers logging db change after disabling log_slow_extra_db. */ + + /* When no schema is selected, str is null on the primary and empty-string on replicas ¯\_(ツ)_/¯. + * It does not matter much here, but leaving a comment in case it matters in the future. + * This "weirdness" is the source of Bug#115203. */ + const char *db4file = thd->db().str ? thd->db().str : ""; + + /* In my patch for Bug#106645, I am allowing myself to change the format of Id. + * This avoids a snprintf, and is more consistent with Thread_id below (which looks better). + * IMHO, adding Db is the right time to improve on the formatting of this line, + * but feel free to revert if you do not like it. */ + if (my_b_printf(&log_file, "# User@Host: %s Id: %lu Db: %s\n", user_host, (ulong)thd->thread_id(), db4file) == (uint)-1) + goto err; + } } /* For slow query log */ @@ -802,11 +833,23 @@ bool File_query_log::write_slow(THD *thd, ulonglong current_utime, goto err; /* purecov: inspected */ } - if (thd->db().str && strcmp(thd->db().str, db)) { // Database changed + /* Adding "&& thd->db().length > 0" would solve Bug#115203, + * but as out of scope of Bug#106645, not done in this patch + * (feel free to fix Bug#115203 before merging this patch). */ + if (log_db_change && thd->db().str /*&& thd->db().length > 0*/ && strcmp(thd->db().str, db)) { if (my_b_printf(&log_file, "use %s;\n", thd->db().str) == (uint)-1) goto err; my_stpcpy(db, thd->db().str); } + + /* In my patch for Bug#106645, I am allowing myself to change the initial assignment of end + * from buff to NULL and assigning it to buff here. IMHO it makes clearer that all usage of buff + * above are irrelevant to the code below, but feel free to revert if you do not like it. */ + /* Re-assigning end to make clear it is not used in above. + * We cannot declare / initialize here as "goto err" would cross + * a declaration / initialization boundary. */ + end = buff; + if (thd->stmt_depends_on_first_successful_insert_id_in_prev_stmt) { end = my_stpcpy(end, ",last_insert_id="); end = longlong10_to_str( @@ -840,10 +883,12 @@ bool File_query_log::write_slow(THD *thd, ulonglong current_utime, } if (is_command) { end = strxmov(buff, "# administrator command: ", NullS); - buff_len = (ulong)(end - buff); DBUG_EXECUTE_IF("simulate_slow_log_write_error", { DBUG_SET("+d,simulate_file_write_error"); }); - if (my_b_write(&log_file, (uchar *)buff, buff_len)) goto err; + /* In my patch for Bug#106645, I am allowing myself to remove the usage of the buff_len + * variable in below. IMHO, it is better code as it does not reuse this variable, + * but feel free to revert if you do not like it. */ + if (my_b_write(&log_file, (uchar *)buff, (ulong)(end - buff))) goto err; } if (my_b_write(&log_file, pointer_cast(sql_text), sql_text_len) || diff --git a/sql/mysqld.cc b/sql/mysqld.cc index 094863f3df51..077670f43eab 100644 --- a/sql/mysqld.cc +++ b/sql/mysqld.cc @@ -1200,6 +1200,7 @@ ulonglong log_output_options; bool opt_log_queries_not_using_indexes = false; ulong opt_log_throttle_queries_not_using_indexes = 0; bool opt_log_slow_extra = false; +bool opt_log_slow_extra_db = true; bool opt_disable_networking = false, opt_skip_show_db = false; bool opt_skip_name_resolve = false; bool server_id_supplied = false; diff --git a/sql/mysqld.h b/sql/mysqld.h index 7d8980599f86..aa478000da11 100644 --- a/sql/mysqld.h +++ b/sql/mysqld.h @@ -167,6 +167,7 @@ extern ulonglong log_output_options; extern bool opt_log_queries_not_using_indexes; extern ulong opt_log_throttle_queries_not_using_indexes; extern bool opt_log_slow_extra; +extern bool opt_log_slow_extra_db; extern bool opt_disable_networking, opt_skip_show_db; extern bool opt_skip_name_resolve; extern bool opt_help; diff --git a/sql/sys_vars.cc b/sql/sys_vars.cc index 6ada71fcc290..d9c22768f9f4 100644 --- a/sql/sys_vars.cc +++ b/sql/sys_vars.cc @@ -5854,6 +5854,9 @@ static Sys_var_bool Sys_slow_query_log( NOT_IN_BINLOG, ON_CHECK(nullptr), ON_UPDATE(fix_slow_log_state)); static bool check_slow_log_extra(sys_var *, THD *thd, set_var *) { + /* This function is called by check_slow_log_extra_db. If something specific + * to slow_log_extra (not slow_log_extra_db) is added here, consider + * updating check_slow_log_extra_db. */ // If FILE is not one of the log-targets, succeed but warn! if (!(log_output_options & LOG_FILE)) push_warning( @@ -5872,6 +5875,19 @@ static Sys_var_bool Sys_slow_log_extra( NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(check_slow_log_extra), ON_UPDATE(nullptr)); +static bool check_slow_log_extra_db(sys_var * sysv, THD *thd, set_var * setv) { + /* Exactly the same as check_slow_log_extra, let's not duplicate code. */ + return check_slow_log_extra(sysv, thd, setv); +} + +static Sys_var_bool Sys_slow_log_extra_db( + "log_slow_extra_db", + "Print db to the slow query log file. Has no effect on " + "logging to table.", + GLOBAL_VAR(opt_log_slow_extra_db), CMD_LINE(OPT_ARG), DEFAULT(true), + NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(check_slow_log_extra_db), + ON_UPDATE(nullptr)); + static bool check_not_empty_set(sys_var *, THD *, set_var *var) { return var->save_result.ulonglong_value == 0; }