Description:
Hi,
mysqldumpslow breaks on "administrator command". See how to repeat for details.
Thanks for looking into this,
Jean-François Gagné
How to repeat:
# Create a 8.4.0 sandbox. If using 8.0.37, we get similar results.
c="-c slow_query_log_file=slow.log -c slow_query_log=ON"
c="$c -c long_query_time=10 -c log_output=FILE"
dbdeployer deploy single 8.4.0 $c
# Create a schema, a table, and insert a row in that table
./use <<< "
create database test_jfg;
create table test_jfg.t(id int);
insert into test_jfg.t values (1);"
# Generate a slow query.
./use test_jfg <<< "set session long_query_time=0.5; select sleep(1), t.* from test_jfg.t;" > /dev/null
# Run mysqldumpslow, result as expected.
. sb_include # For $BASEDIR.
$BASEDIR/bin/mysqldumpslow data/slow.log
Reading mysql slow query log from data/slow.log
Count: 1 Time=1.01s (1s) Lock=0.00s (0s) Rows=1.0 (1), msandbox[msandbox]@localhost
select sleep(N), t.* from test_jfg.t
# Generate slow querieds with "administrator command".
./use <<< "set session long_query_time=0; use test_jfg; select sleep(1), t.* from t;" > /dev/null
# Run mysqldumpslow, the "administrator command" do not report as the right user and 2 slow queries as "#".
$BASEDIR/bin/mysqldumpslow data/slow.log
Reading mysql slow query log from data/slow.log
Count: 1 Time=1.01s (1s) Lock=0.00s (0s) Rows=1.0 (1), msandbox[msandbox]@localhost
select sleep(N), t.* from test_jfg.t
Count: 1 Time=1.00s (1s) Lock=0.00s (0s) Rows=1.0 (1), msandbox[msandbox]@localhost
select sleep(N), t.* from t
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), msandbox[msandbox]@localhost
set session long_query_time=N
Count: 2 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.5 (1), msandbox[msandbox]@localhost
#
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (1), msandbox[msandbox]@localhost
SELECT DATABASE()
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), 0users@0hosts
administrator command: Init DB
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), 0users@0hosts
administrator command: Quit
Suggested fix:
From what I understand, the separator in [1] considers lines starting with "# administrator command:" proceeded by a line like "SET timestamp=1716407122;" as a new slow log entry.
[1]: https://github.com/mysql/mysql-server/blob/mysql-8.4.0/scripts/mysqldumpslow.pl.in#L92
If we replace "# admin" with "-- admin", the output is better. This is only a workaround though, my Perl-foo is not good-enough for seeing a quick fix.
sed -e "s/^# administrator command:/-- administrator command:/" data/slow.log > data/slow1.log
$BASEDIR/bin/mysqldumpslow data/slow1.log
Reading mysql slow query log from data/slow1.log
Count: 1 Time=1.01s (1s) Lock=0.00s (0s) Rows=1.0 (1), msandbox[msandbox]@localhost
select sleep(N), t.* from test_jfg.t
Count: 1 Time=1.00s (1s) Lock=0.00s (0s) Rows=1.0 (1), msandbox[msandbox]@localhost
select sleep(N), t.* from t
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (1), msandbox[msandbox]@localhost
-- administrator command: Init DB
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), msandbox[msandbox]@localhost
set session long_query_time=N
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (1), msandbox[msandbox]@localhost
SELECT DATABASE()
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), msandbox[msandbox]@localhost
-- administrator command: Quit
