MySQL Bugs: #106645: Slow query log is not logging database/schema name

Bug #106645	Slow query log is not logging database/schema name
Submitted:	5 Mar 2022 1:27	Modified:	18 Jul 2024 14:16
Reporter:	Agustín G	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S4 (Feature request)
Version:	5.7,8.0	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	Contribution

Description:
The slow query log is not showing any information on which database/schema the query applied to. Even if we enable log_slow_extra on 8.0, we won't get it.

How to repeat:
Enable slow query log (optionally, with log_slow_extra) and see how logged queries don't have the schema info:

# Time: 2022-03-05T00:57:38.881881Z
# User@Host: root[root] @ localhost []  Id:    14
# Query_time: 0.000325  Lock_time: 0.000175 Rows_sent: 0  Rows_examined: 0 Thread_id: 14 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 54 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 1 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: 2022-03-05T00:57:38.881556Z End: 2022-03-05T00:57:38.881881Z
SET timestamp=1646441858;
select * from t1;

Suggested fix:
The slow query log should include this important piece of information.

Hello Agustín G,

Thank you for the report and feedback.
Imho, when the destination for logging of slow query log is *file* then currently by default 4 fields (Query_time, Lock_time, Rows_sent and Rows_examined) are logged but with log_slow_extra system variable (available as of MySQL 8.0.14) enabled then it write some more extra fields to FILE. More details is here https://dev.mysql.com/doc/refman/8.0/en/slow-query-log.html

But the information, you are looking such as "db" is available when the destination for logging is set to TABLE.

mysql> show create table mysql.slow_log\G
*************************** 1. row ***************************
       Table: slow_log
Create Table: CREATE TABLE `slow_log` (
  `start_time` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
  `user_host` mediumtext NOT NULL,
  `query_time` time(6) NOT NULL,
  `lock_time` time(6) NOT NULL,
  `rows_sent` int NOT NULL,
  `rows_examined` int NOT NULL,
  `db` varchar(512) NOT NULL,
  `last_insert_id` int NOT NULL,
  `insert_id` int NOT NULL,
  `server_id` int unsigned NOT NULL,
  `sql_text` mediumblob NOT NULL,
  `thread_id` bigint unsigned NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8mb3 COMMENT='Slow log'
1 row in set (0.00 sec)

Verifying this as a feature request to log schema information to the file along with existing fields.

regards,
Umesh

Hi,

I am working on a contribution for implementing this feature request.  I would welcome feedback.

The branch where I am working is [1].  This branch contains a brain-dump of my work [2].  Commits in this branch will be messy, I created a Fake PR [3] to easily see the progress on the contribution (you can like this PR to show me you think this work is important).  The README [4] contains links to the brain-dump and the Fake PR.  I will eventually update the README the contribution is ready/submitted (example of a Contrib Fake PR on another work in [4]).

[1]: https://github.com/jfg956/mysql-server/tree/mysql-8.4.0_bug106645

[2]: https://github.com/jfg956/mysql-server/blob/mysql-8.4.0_bug106645/jfg_brain_dump.md

[3]: https://github.com/jfg956/mysql-server/pull/8

[4]: https://github.com/jfg956/mysql-server/pull/5

This bug report is not the right place for feedback.  These are good places:

- In the Fake PR on GitHub [3] (comments or reviews);

- In the matching announcements on LinkedIn [5], X/Twitter [6] or Facebook [7];

- In the #contrib_bug106645 channel in MySQL Community Slack [8];

- DM in Slack, LinkedIn, X/Twitter or Facebook, or via email: jfg.mysql AT gmail DOT com.

[5]: https://www.linkedin.com/posts/jfg956_mysql-activity-7195819671365771264-yGET/

[6]: https://twitter.com/jfg956/status/1790054137628946753

[7]: https://www.facebook.com/jfg956/posts/pfbid033xGW9nns1QF6AYZR248DwhUtjhF6Z2sfkj9JMvAE38RTw...

[8]: https://slack.lefred.be/

Thanks,

Jean-François Gagné

Hi Jean-François,

This is awesome. +1 to your work on it!

Thanks for taking the time to implement it :)

> I am working on a contribution for implementing this feature request.

I am almost ready to submit my contribution.  I wrote a RFC blog post about it [1] and it points to a RFC PR [2] with the contribution on which I would like feedback.

[1]: https://jfg-mysql.blogspot.com/2024/06/rfc-database-schema-in-slow-query-log-file.html

[2]: https://github.com/jfg956/mysql-server/pull/9

Thanks, J-F

More about this contribution in https://github.com/jfg956/mysql-server/pull/11 (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: bug#106645.patch (application/octet-stream, text), 26.59 KiB.

I cannot add the "Contribution" tag as this is not my bug, can this be done by MySQL Verification Team or OP.  And btw, when submitting a contribution via the Contributions tab, this should "auto-add" the "Contribution" tag.  More about this tag in [1], quote below.

[1]: https://forums.oracle.com/ords/apexds/post/contributing-code-to-mysql-8037

> Submitting a Patch - If you have a patch for an existing bug or feature request, attach it to your bug report. (If there is no corresponding bug report yet, create one.) Add the tag "Contribution" to the bug report, to make sure that it shows up in the patch contributions pipeline, which is used internally to make sure your patch gets the attention of a MySQL engineer.

Some notes about my above contribution extracted from https://github.com/jfg956/mysql-server/pull/11

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

This patch applies on 8.4.0, 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 patch 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, but I am notified by Oracle that this would be better, I will update the patch).

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. 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 [0]. 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).

[0]: https://dev.mysql.com/doc/refman/8.4/en/server-system-variables.html#sysvar_log_slow_extra

Examples of logs with and without the feature enabled in [1].

[1]: https://github.com/jfg956/mysql-server/pull/11#issuecomment-2223427044

This patch 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 [0]). 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 [1]). 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 (links below). I will let Oracle decide if these should be included or reverted (I can adapt the PR if they ask me to).

- Remove buff_len for administrator command [2a]
- With Db, make Id format consistent with Thread_id (already mentioned above) [2b]
- Inline the declaration of buff_len [2c]
- Making usage of end clearer with better assignments [2d]

[2a]: https://github.com/jfg956/mysql-server/pull/8/commits/cc3cbb3a85e2bd5dea97279c9c9782665ef9...

[2b]: https://github.com/jfg956/mysql-server/pull/8/commits/4899363462a638e5b3ded4f40de5cd50e45f...

[2c]: https://github.com/jfg956/mysql-server/pull/8/commits/a36225c5fb806b695ab3e19c4286158e2180...

[2d]: https://github.com/jfg956/mysql-server/pull/8/commits/8d44f3090d86ebf3f5acb35143994c5e6e62...

Thanks for considering my contribution, J-F

Adding the contribution tag