RFC: Database / Schema in the Slow Query Log File

A month ago, I announced that I am working on a MySQL Contribution to add database / schema in the slow query log file (bug report, LinkedIn, Twitter, Facebook, and MySQL Community Slack).  My contribution is ready, and before submitting it, I would like feedback, so I am writing this post as a Request for Comments (RFC).  If you are in a hurry, you can go directly to the RFC Fake PR.  But what is a Fake PR ?  It is part of my way of working on MySQL Contributions, which I describe below, and on which I would also welcome feedback.  Something else covered in this post are the design choices made for this contribution, and again, I would welcome your feedback on them (I can make adjustments before submitting my contribution).  In this post, I also explain why having the database / schema in the slow query log file is important.

This post is written in the context of my work on MySQL at Aiven: check our careers page or blog to know more about us.

Before continuing, if you think this work is important, click the "Affects me" Button in Bug #106645, and you might also want to subscribe to email updates.

Fake PRs and my Way of Working on MySQL Contributions

(If you are not interested in this, you can jump to the next section: Database / Schema in the Slow Query Log File)

In this section, I cover what I call a Fake PR, and more broadly, the way I work on MySQL Contributions.  This obviously involves a fork of the mysql-server GitHub repository.

Once I identify something I will work on, I create a branch for this in my fork.  For checking this branch out, I use git-worktree.  Work-trees allow working on more than one branch at the same time, thanks Laurynas for mentioning them in your post on Tips for making MySQL builds & tests faster, this is a great tip !

This branch is what I call a Work Branch (the work branch for database / schema in the slow query log file is mysql-8.4.0_bug106645).  The content of a work branch is messy: many unstructured and usually poorly commented commits.  Part of what explains this mess is that I might push a commit Work in Progress (WIP) as a backup of my work at the end of each day.  To have a unified view on the mess, I have a Work Fake PR (link to this PR for database / schema in the slow query log file).  This PR is "Fake" because it will never get merged, and it stays in "Draft" to avoid merging by mistake.  You can subscribe to this PR to see progress (but you will get all the mess), you can also comment in it if you want to help or give early feedback, or you can also wait for the work to be completed and for a RFC to be published.

The work branch contains a brain dump.  This is where I put notes on my work, which include my next steps, TODOs, and a lot more.  It is also messy.  You do not have to read it, it is mostly for my own organization, but there might be interesting gems in there.

When a contribution is ready, I create a RFC Branch and a matching RFC Fake PR (links to branch and Fake PR for database / schema in the slow query log file).  There is usually a single commit in there for all what was done in the Work Branch.  The text of the RFC PR includes all relevant information to review the contribution and it is where you can give feedback on the "almost final" work.  After enough time was given for feedback, I will submit the contribution as a patch file in the bug report.

To easily find everything, I add notes and links to the README in the Work Branch (link to the README for database / schema in the slow query log file, the links are clickable in the branch view).

I did another contribution almost matching this process.  The branch for my work on Bug #91737 (Please log GTID_EXECUTED when running RESET MASTER) contains, in addition to the modified files, a brain dump, and a README with links to a Work Fake PR and a Contrib Fake PR (this work was "small enough" and IMHO did not need a RFC).  And this was contributed as a patch file in the bug report / feature request (in the bug report, I also shared the link to the Contrib Fake PR in which there is more information and in case someone wants to give feedback).

For future work, I plan to make announcements (in the bug report and on social media), create a Work Branch with a brain dump and the matching Work Fake PR, eventually create a RFC Fake PR and publish a RFC Blog Post, maybe create a Contrib Fake PR (if the RFC Fake PR becomes messy), and finally submit the contribution as a patch in the bug report.  I might skip some of these depending on the importance of the work (the RESET MASTER work was not "big" enough for an announcement and RFC).  If you have feedback on this workflow, feel free to share them as a comment to this post or via LinkedIn, Twitter, Facebook, MySQL Community Slack (in #contributions or via DM @jfgagne), or email at jfg DOT mysql AT gmail.com).

And one last thing: because my MySQL contributions are made under the OCA signed by Aiven, I had to create a new Oracle Account: J-F Aiven Gagné.  I am mostly using it for contributions (except for Bug #114671 which I created as a test).  Most of my MySQL bugs activities are done with the account Jean-François Gagné (with the exception of some bugs created in 2018 when I was logged in with a legacy account: J-F Legacy Gagné).  Yes, I am now stuck with at least three Oracle accounts :-( !

Database / Schema in the Slow Query Log File

(If you are not interested in this, you can jump to the next section: Design Choices)

Currently, when adding an entry in the slow query log file, MySQL does not include the database / schema in which the query was run.  This is missing since 2006 (Bug #19046: slow query log should include the affected database).  More recently, in 2022, it was asked again in Bug #106645 (Slow query log is not logging database/schema name), and I am anchoring my work on this more recent report.

As mentioned in Bug #106645, the slow query log table (mysql.slow_log) contains a db column which is not written in the slow query log file (slow query log entries are either in a table or in a file, controlled by the global variable log_output).  So not having the database / schema in the file looks like an involuntary omission.

I understand that this work was not a high priority for Oracle.  Most of the time, a human seeing a query in the slow query log file is able to gather in which schema it was run.  There is also a way to infer in which schema a query is run by looking at the line "use <schema>;" in the file: if it is there, the query is run in this schema, and if not, the query is run in the same schema as the previous slow query (or in "no schema").  But this implementation deserves to be improved because it is impractical (knowing the schema of the current query needs knowing the schema of the previous query, which is a recursive problem not well suited to "tailing" the slow query log file: it only works well when reading the file from the beginning).

Also, multi-tenant environments and automation are additional reasons for having the database / schema in the slow query log file.  In a multi-tenant environment, different schemas might contain the same table, which makes it harder to infer in which schema a query was run.  Also, automation using the slow query log file as an input often has to know in which schema a query is run (as an example, to be able to run an EXPLAIN).  And again, the "use" line in the file is hard to leverage, hence the need for something better.

And I know I am repeating myself, but it is a good signal to give Oracle: if you think this work is important, click the Affects me Button in Bug #106645, and you might also want to subscribe to email updates.  You can also support my work on this by putting a "thumbs-up" on the Work Fake PR or on the RFC Fake PR.

Design Choices

(If you want a shorter version of this section, you can simply read the RFC Fake PR and then jump to the next section: Other Findings while Doing this Work)

Adding the database / schema to the slow query log file looks like a straightforward change.  However, like many things in IT, it is not trivial !  I see four design choices that are important to discuss, all of which I would like to have feedback on:

• backward compatibility,
• new field or "use ...";
• position and name of the new field;
• what to do when a query is run in "no schema".

For me, the first important thing for this change is to avoid breaking backward compatibility.  Changing the format of the slow query log file might break tooling parsing this file, and even if this is allowed in a new MySQL version, I would prefer not doing this.  The way I planned to do that is by putting this change behind a feature flag / global variable.  There are already many global variables controlling the slow query log (log_slow_admin_statements, log_slow_replica_statements, long_query_time and min_examined_row_limit) and one of them is precisely controlling the slow query log file: log_slow_extra.  Un-originally, I named the variable controlling the inclusion of database / schema in the slow query log file log_slow_extra_db (db as the name of the field I add to the file, it could change if I need to apply feedback on my work before contributing).  It is ON by default in my contribution, and can be set to OFF to keep the old behavior.  One interesting thing about this is that it allows back-porting this change in 8.4 and 8.0 with the default to OFF.  Eventually, this global variable should 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).

At first, my idea was to add a new field in the slow query log file.  Even if this is what I ended up doing, I saw an interesting alternative while doing this work and it is worth mentioning it.  While staring at the code, I realized that the schema / database is somehow already in the slow query log file.  When the current slow query is in a different schema than the previous slow query, a line "use <schema>;" is in the file (link to the code).  This implementation is not very useful (already discussed in the previous section), but it could be extended to make the "use" line present for all queries.  This would have the advantage of not changing the format of the file, but it is not well suited for queries not run in a specific schema.  The absence of the "use" line could mean the query was not run in a specific schema (like it is currently implemented), but this was not to my liking, so I stuck with the new field.  Let me know if you think this is ok or if this needs to be changed by voting on the matching comment in the RFC PR.

One last thing about the "use" line, with the new field in the slow query log file, this is never printed.  If this feels wrong to you, let me know.  And btw, I do not think this "use" line in the slow query log file is documented, but as I am removing it in my contribution, I decided not to open a bug about this.

As you can infer from above, to add the database / schema in the slow query log file, I add a new field.  Before giving more details about this new field, let's give an example of a query in the current slow query log file.

# Time: 2024-05-10T17:44:36.400424Z
# User@Host: msandbox[msandbox] @ localhost []  Id:    12
# Query_time: 0.000237  Lock_time: 0.000004 Rows_sent: 0  Rows_examined: 0
SET timestamp=1715363076;
select * from t;

For me, the best place to add the new field is on the "User@Host" line.  I named this field "Db".  An example of a query in the slow query log file with this field is below.

# Time: 2024-05-23T18:45:31.526893Z
# User@Host: msandbox[msandbox] @ localhost []  Id:    12  Db: test_jfg
# Query_time: 1.000486  Lock_time: 0.000003 Rows_sent: 1  Rows_examined: 1
SET timestamp=1716489930;
select sleep(1), t.* from t;

I chose to name this new field "Db" because of the db column in the table mysql.slow_log.  Another name could have been "Schema".  Let me know if you think this is ok or if this needs to be changed by voting on the matching comment in the RFC PR.

The last thing to cover is what to log when a query is run in no specific schema.  My first idea, and what I currently implemented, is having a "NoDb" as shown below.

# Time: 2024-05-31T18:46:25.545533Z
# User@Host: msandbox[msandbox] @ localhost []  Id:    23  NoDb
# Query_time: 0.026993  Lock_time: 0.000003 Rows_sent: 0  Rows_examined: 0
SET timestamp=1717181185;
create database test_jfg4;

While working on this, I also thought about having "Db: " instead of "NoDb" (basically, the empty-string db).  I see pros and cons on both, so I kept "NoDb".  Let me know if you think this is ok or if this needs to be changed by voting on the matching comment in the RFC PR.

Other Findings while Doing this Work

While working on adding database / schema in the slow query log file, I found a few other interesting things that are worth sharing:

• dbdeployer not working in replicated mode with 8.4.0;
• replication setup documentation missing SOURCE_SSL = 1;
• documentation not mentioning RESET MASTER replacement;
• P_S digest table (and slow query log table) unexpectedly reports created database on replica;
• empty "use ;" on replica in slow query log file;
• log_slow_extra duplicates session number in Id and Thread_id.

First, dbdeployer, a tool for MySQL sandboxes about which I wrote a Mac Tutorial not too long ago, is not working well in replicated mode with MySQL 8.4.  Such breakage was expected at some point as dbdeployer is unmaintained, but I was surprised to see this happens so quickly.  The standalone and multiple modes still work, and there is a workaround for manually setting up a replication environment from a multiple deployment.  I shared this workaround in MySQL Community Slack (and it can also be found in the SOURCE_SLL bug report mentioned below).  If you want to be part of the discussion about the future of dbdeployer, join the #dbdeployer-for-life channel in MySQL Community Slack.

While manually setting up replication in a dbdeployer multiple sandbox (workaround for above), I was following the documentation and something was wrong, so I opened Bug #115179: Replication Setup Documentation missing SOURCE_SSL = 1.  At the same time, as I am not yet used to the new "master-less and slave-less" commands, I had a hard time finding the replacement for RESET MASTER and opened Bug #115187: Doc do not mention replacement for RESET MASTER (in case you do not know, it is RESET BINARY LOGS AND GTIDS, and yes, it is weird that this command mentions GTID while GTID_MODE is still OFF by default).  In this documentation bug, I also mention that MySQL 8.4 should probably still support RESET MASTER in deprecated mode to ease upgrading from 8.0 (the absence of the replacement command in 8.0 - introduced in 8.2 - and the removal of the old command in 8.4 make upgrading harder than it should).  Partially related to this, and it was verified, I opened Bug #115310: Granting SET_USER_ID breaks replication from 8.0 to 8.4.

One of the tests I did for this change is making sure adding database / schema in the slow query log file worked for replication.  It was a useful test as it allowed me to find a bug in my code and to find two weird replication behaviors / bugs in MySQL.

The first weird behavior, which is a verified bug, is that when creating a new database / schema, the database / schema is not well set on replicas (it is on the primary).  I will let you check the bug report for details (Bug #115189: P_S Digest table unexpectedly reports created database on replica).  For the short interesting story, I found this while testing my code and chose to report it for the Performance Schema "digest" table (events_statements_summary_by_digest) as this is where this behavior was visible.  I ended up completing the bug report for the slow query log table after realizing that this behavior was also visible there.  And this is when the other weird behavior started to show up...

The second weird behavior, which is also a verified bug, is that no schema is sometimes presented at NULL (as in the digest table) and sometimes as the empty-string (as in the slow query log table).  And to make things more complicated, the variable storing this information is also sometimes NULL for "no schema" (on the primary) and the empty-string (on replicas).  As at first, I only considered the NULL case, my tests were showing NoDb on the primary and "Db: " (an empty-string Db) on the replica (and this is where I got the idea of having the empty-string db in the file instead of NoDb).  I fixed my code and thought that this might affect the "use" line and indeed it did (not surprising: there was a bug in my code, and I based my code on the way the "use" line is written in the file).  I will also let you check the bug report for details (Bug #115203: Empty "use ;" on replica in slow query log file).  I suggested a fix in the bug report, and I also added the fix as a comment in my contribution.

Lastly, when checking the format of the slow query log file, I saw that with log_slow_extra, the session number / thread id is logged in both the "Id" and "Thread_id" fields, which is duplicated information.  For this, and it was verified, I opened Bug #115285: log_slow_extra duplicates session number in Id and Thread_id.

That is it.  Thanks for reading all this, and thanks for your interest in my work on MySQL.  And please provide feedback (even if it is only a thumbs-up) in the RFC Fake PR.  And if you prefer, you can provide feedback as a comment to this post, or via LinkedIn, Twitter, Facebook, MySQL Community Slack (I am @jfgagne there), or email at jfg DOT mysql AT gmail.com).