Skip to content

Contrib Fake PR: Implement Bug#106645: Slow query log is not logging database/schema name.#11

Draft
jfg956 wants to merge 1 commit intomysql-8.4.0_for_fake_prsfrom
mysql-8.4.0_bug106645_contrib
Draft

Contrib Fake PR: Implement Bug#106645: Slow query log is not logging database/schema name.#11
jfg956 wants to merge 1 commit intomysql-8.4.0_for_fake_prsfrom
mysql-8.4.0_bug106645_contrib

Conversation

@jfg956
Copy link
Owner

@jfg956 jfg956 commented Jul 10, 2024 •
edited
Loading

This PR adds database / schema in the slow query log file, implementing the feature request Bug#106645: Slow query log is not logging database/schema name.

In case, at the same time as merging this contribution, it makes sense to fix Bug#115203, this PR also includes a commented fix for that bug (Empty "use ;" on replica in slow query log file).

This is a "Contrib Fake PR". It is there so people can comment on this work in case it needs adjustments. This has be contributed on 2024-07-12 as a patch file in Bug#106645. More about this in the RFC blog post, section Fake PRs and my Way of Working on MySQL Contributions.

This PR merges on 8.4.0, and the corresponding patch file applies on 8.4.1 and 9.0.0. It does not apply on 8.0.38, but the commit of this PR can be cherry-picked in a branch from the 8.0.38 tag. The mtr tests of this work pass in all of 8.0.38, 8.4.0, 8.4.1 and 9.0.0.

For implementing database / schema in the slow query log file, this PR introduces a new global variable: log_slow_extra_db. It is ON by default, and can be set to OFF to keep the current 9.0, 8.4 and 8.0 behavior (in case of changing the format of the slow query log file breaks tooling parsing the file). This variable should eventually be deprecated to reduce code complexity (I have chosen not to introduce it as deprecated, if Oracle prefers that and notifies me, I will update the PR).

Ideally, in addition to being included in a next Innovation Release, this would be back-ported in 8.4 and 8.0. For back-porting, the default value of the global variable log_slow_extra_db should be set to false to avoid a breaking change.

Note that with log_slow_extra_db = ON, all use ... are removed from the slow query log file.

Also note that with log_slow_extra_db = ON, there is a minor change in the format of the User@Host line of the slow query log file. Before, it was # User@Host: %s Id: %s, with Id: %s being a %5u. With log_slow_extra_db = ON, it is # User@Host: %s Id: %lu Db: %s which is consistent with the way Thread_id is logged with log_slow_extra. It looks like the right time to improve on the formatting of this line (adding a new field and this change being behind a feature-flag), but Oracle can revert this if they do not like it (I can adapt the PR if they ask me to).

Examples of logs with and without the feature enabled in the 1st PR comment.

This PR also includes the three mtr tests below. The first two are for testing this new feature, and the last one, for adding a missing test on an existing feature (log_slow_extra). The third test is inspired from the second, and even if this test is not directly related to this work, adding it looked like the right thing to do (and it was easy).

  1. sys_vars.log_slow_extra_db_basic
  2. sys_vars.log_slow_extra_db_func
  3. sys_vars.log_slow_extra_func

There is a limit to this implementation, inherited from Bug#115526: Invalid multi-line "use" in slow query log file with multi-line schema. When logging a slow query in a multi-line schema, the Db field is on two lines (see example in 1st PR comment). It could be escaped, but depending on how the existing bug will be fixed, this might need a rework. So I am leaving this to be addressed at the same time as Bug#115526. Also, IMHO, someone using a multi-line schema is looking for trouble, so ¯_(ツ)_/¯.

While doing this work, I "played with fire" and tried improving the implementation of the function File_query_log::write_slow. This led to four improvements, which I isolated in four different commits in the Work Branch. I will let Oracle decide if these should be included or reverted (I can adapt the PR if they ask me to).

More JFG development notes:

@jfg956 jfg956 mentioned this pull request Jul 10, 2024
Closed
@jfg956
Copy link
Owner Author

jfg956 commented Jul 11, 2024 •
edited
Loading

Examples of Logs with and without the feature enabled

dbdeployer deploy single mysql_8.4.0 -c slow_query_log_file=slow.log -c slow_query_log=ON

# Previous behavior with Id as a %5u and "use test_jfg;" in the log, new behavior below.
db=test_jfg
./use <<< "set global log_slow_extra_db = OFF"
./use <<< "create database $db; create table $db.t(id int); insert into $db.t values (1);"
./use $db <<< "set session long_query_time=0.5; select sleep(1), t.* from t;" > /dev/null
cat data/slow.log
/home/jgagne/opt/mysql/mysql_8.4.0/bin/mysqld, Version: 8.4.0 (Source distribution). started with:
Tcp port: 8400  Unix socket: /tmp/mysql_sandbox8400.sock
Time                 Id Command    Argument
# Time: 2024-07-11T17:41:28.546157Z
# User@Host: msandbox[msandbox] @ localhost []  Id:    12
# Query_time: 1.000453  Lock_time: 0.000003 Rows_sent: 1  Rows_examined: 1
use test_jfg;
SET timestamp=1720719687;
select sleep(1), t.* from t;

# New behavior with Id as a %lu (no extra spaces before the data) and without "use test_jfg2;".
# More tests below with a multi-line schema.
db=test_jfg2
./use <<< "set global log_slow_extra_db = ON"
./use <<< "create database $db; create table $db.t(id int); insert into $db.t values (1);"
./use $db <<< "set session long_query_time=0.5; select sleep(1), t.* from t;" > /dev/null
./use <<< "set session long_query_time=0.5; select sleep(1), t.* from $db.t;" > /dev/null
tail -n 10 data/slow.log
# Time: 2024-07-11T17:41:59.444713Z
# User@Host: msandbox[msandbox] @ localhost []  Id: 15  Db: test_jfg2
# Query_time: 1.000476  Lock_time: 0.000003 Rows_sent: 1  Rows_examined: 1
SET timestamp=1720719718;
select sleep(1), t.* from t;
# Time: 2024-07-11T17:42:00.466497Z
# User@Host: msandbox[msandbox] @ localhost []  Id: 16  Db: 
# Query_time: 1.000522  Lock_time: 0.000004 Rows_sent: 1  Rows_examined: 1
SET timestamp=1720719719;
select sleep(1), t.* from test_jfg2.t;

# Above does not show, there is a "space" after "Db:" in the 2nd entry.
# This is move obvious in below.
tail -n 5 data/slow.log | cat -E
# Time: 2024-07-11T17:42:00.466497Z$
# User@Host: msandbox[msandbox] @ localhost []  Id: 16  Db: $
# Query_time: 1.000522  Lock_time: 0.000004 Rows_sent: 1  Rows_examined: 1$
SET timestamp=1720719719;$
select sleep(1), t.* from test_jfg2.t;$

# And finally, the multi-line schema "restriction".
db="test
jfg"
./use <<< "create database \`$db\`; create table \`$db\`.t(id int); insert into \`$db\`.t values (1);"
./use "$db" <<< "set session long_query_time=0.5; select sleep(1), t.* from t;" > /dev/null
tail -n 6 data/slow.log
# Time: 2024-07-11T17:43:27.953093Z
# User@Host: msandbox[msandbox] @ localhost []  Id: 18  Db: test
jfg
# Query_time: 1.000449  Lock_time: 0.000004 Rows_sent: 1  Rows_examined: 1
SET timestamp=1720719806;
select sleep(1), t.* from t;

@jfg956 jfg956 mentioned this pull request Nov 22, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

1 participant

@jfg956