| Bug #112414 | log_slow_admin_statements cause store procedure record dml in slow log | ||
|---|---|---|---|
| Submitted: | 21 Sep 2023 13:45 | Modified: | 26 Sep 2023 9:15 |
| Reporter: | Xuming Zhang | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Logging | Severity: | S3 (Non-critical) |
| Version: | 8.0 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[22 Sep 2023 9:41]
MySQL Verification Team
Hi Mr. Zhang, Thank you for your bug report. However, we are unable to repeat your behaviour with 8.0.34 and 8.1.0. Your test case returns all queries for both procedures, irrespective of the presence of the administrative command: +------+ | a1 | +------+ | 1 | | 2 | | 3 | | 4 | | 5 | +------+ +------+ | a1 | +------+ | 1 | | 2 | | 3 | | 4 | | 5 | +------+ +------+ | a1 | +------+ | 1 | | 2 | | 3 | | 4 | | 5 | +------+ +------+ | a1 | +------+ | 1 | | 2 | | 3 | | 4 | | 5 | +------+ +------+ | a1 | +------+ | 1 | | 2 | | 3 | | 4 | | 5 | +------+ +---------+---------+----------+----------+ | Table | Op | Msg_type | Msg_text | +---------+---------+----------+----------+ | test.t1 | analyze | status | OK | +---------+---------+----------+----------+ +------+ | a1 | +------+ | 1 | | 2 | | 3 | | 4 | | 5 | +------+ +------+ | a1 | +------+ | 1 | | 2 | | 3 | | 4 | | 5 | +------+ +------+ | a1 | +------+ | 1 | | 2 | | 3 | | 4 | | 5 | +------+ +------+ | a1 | +------+ | 1 | | 2 | | 3 | | 4 | | 5 | +------+ +------+ | a1 | +------+ | 1 | | 2 | | 3 | | 4 | | 5 | +------+ However, we investigated further. It turns out that if we enable slow query logging, everything is logged, irrespective of the value of the long query time, irrespective of whether admin commands are logged or not. Hence, this is a bug, but a bit worse then what you reported. This is now a verified bug.
[26 Sep 2023 9:15]
Xuming Zhang
-- after call sp1; select start_time, query_time, lock_time, rows_examined, sql_text from slow_log; +----------------------------+-----------------+-----------------+---------------+----------+ | start_time | query_time | lock_time | rows_examined | sql_text | +----------------------------+-----------------+-----------------+---------------+----------+ | 2023-09-26 17:13:03.637146 | 00:00:00.071865 | 00:00:00.000000 | 70 | call sp1 | -- after call sp2; select start_time, query_time, lock_time, rows_examined, sql_text from slow_log; +----------------------------+-----------------+-----------------+---------------+---------------------------------------------------------------------------------+ | start_time | query_time | lock_time | rows_examined | sql_text | +----------------------------+-----------------+-----------------+---------------+---------------------------------------------------------------------------------+ | 2023-09-26 17:13:03.637146 | 00:00:00.071865 | 00:00:00.000000 | 70 | call sp1 | | 2023-09-26 17:13:05.767230 | 00:00:00.001504 | 00:00:00.001186 | 1 | select start_time, query_time, lock_time, rows_examined, sql_text from slow_log | | 2023-09-26 17:14:42.921109 | 00:00:00.022933 | 00:00:00.001152 | 7 | insert into t1_tmp0 select * from t1 | | 2023-09-26 17:14:42.921975 | 00:00:00.023799 | 00:00:00.001152 | 14 | select * from t1_tmp0 | | 2023-09-26 17:14:42.922122 | 00:00:00.023946 | 00:00:00.001152 | 14 | SET @i=@i+1 | | 2023-09-26 17:14:42.923384 | 00:00:00.025208 | 00:00:00.001152 | 14 | drop temporary table if exists t1_tmp0 | | 2023-09-26 17:14:42.930501 | 00:00:00.032325 | 00:00:00.001152 | 14 | create temporary table t1_tmp0 (a1 int) engine = memory | | 2023-09-26 17:14:42.935910 | 00:00:00.037734 | 00:00:00.001152 | 21 | insert into t1_tmp0 select * from t1 | | 2023-09-26 17:14:42.936789 | 00:00:00.038613 | 00:00:00.001152 | 28 | select * from t1_tmp0 | | 2023-09-26 17:14:42.936927 | 00:00:00.038751 | 00:00:00.001152 | 28 | SET @i=@i+1 | | 2023-09-26 17:14:42.938185 | 00:00:00.040009 | 00:00:00.001152 | 28 | drop temporary table if exists t1_tmp0 | | 2023-09-26 17:14:42.945290 | 00:00:00.047114 | 00:00:00.001152 | 28 | create temporary table t1_tmp0 (a1 int) engine = memory | | 2023-09-26 17:14:42.950763 | 00:00:00.052587 | 00:00:00.001152 | 35 | insert into t1_tmp0 select * from t1 | | 2023-09-26 17:14:42.951629 | 00:00:00.053453 | 00:00:00.001152 | 42 | select * from t1_tmp0 | | 2023-09-26 17:14:42.951779 | 00:00:00.053603 | 00:00:00.001152 | 42 | SET @i=@i+1 | | 2023-09-26 17:14:42.953028 | 00:00:00.054852 | 00:00:00.001152 | 42 | drop temporary table if exists t1_tmp0 | | 2023-09-26 17:14:42.959913 | 00:00:00.061737 | 00:00:00.001152 | 42 | create temporary table t1_tmp0 (a1 int) engine = memory | | 2023-09-26 17:14:42.965927 | 00:00:00.067751 | 00:00:00.001152 | 49 | insert into t1_tmp0 select * from t1 | | 2023-09-26 17:14:42.966707 | 00:00:00.068531 | 00:00:00.001152 | 56 | select * from t1_tmp0 | | 2023-09-26 17:14:42.966855 | 00:00:00.068679 | 00:00:00.001152 | 56 | SET @i=@i+1 | | 2023-09-26 17:14:42.968056 | 00:00:00.069880 | 00:00:00.001152 | 56 | drop temporary table if exists t1_tmp0 | | 2023-09-26 17:14:42.974898 | 00:00:00.076722 | 00:00:00.001152 | 56 | create temporary table t1_tmp0 (a1 int) engine = memory | | 2023-09-26 17:14:42.980559 | 00:00:00.082383 | 00:00:00.001152 | 63 | insert into t1_tmp0 select * from t1 | | 2023-09-26 17:14:42.981393 | 00:00:00.083217 | 00:00:00.001152 | 70 | select * from t1_tmp0 | | 2023-09-26 17:14:42.981526 | 00:00:00.083350 | 00:00:00.001152 | 70 | SET @i=@i+1 | | 2023-09-26 17:14:42.981684 | 00:00:00.083508 | 00:00:00.000000 | 70 | call sp2 | +----------------------------+-----------------+-----------------+---------------+---------------------------------------------------------------------------------+ 26 rows in set (0.00 sec)
[28 Sep 2023 10:12]
MySQL Verification Team
Thank you Mr. Zhang for your contribution. This is already a verified bug.
Description: If set log_slow_admin_statements = on; and store procedure execute admin sql such as check table/analyze table e.g. It cause other sqls like dml/dql recorded in mysql.slow_log. How to repeat: set global log_slow_admin_statements = on; set global slow_query_log = on; set long_query_time =0; create database test; use test; create table t1(a1 int); insert into t1 values(1); insert into t1 values(2); insert into t1 values(3); insert into t1 values(4); insert into t1 values(5); delimiter // create procedure sp1() begin set @i = 0; while @i < 5 DO drop temporary table if exists t1_tmp0; create temporary table t1_tmp0 (a1 int); insert into t1_tmp0 select * from t1; select * from t1_tmp0; set @i=@i+1; END while; end // create procedure sp2() begin analyze table t1; set @i = 0; while @i < 5 DO drop temporary table if exists t1_tmp0; create temporary table t1_tmp0 (a1 int); insert into t1_tmp0 select * from t1; select * from t1_tmp0; set @i=@i+1; END while; end // delimiter ; truncate mysql.slow_log; call sp1; select * from mysql.slow_log; -- only record call sp1 in slow log call sp2; select * from mysql.slow_log; -- record all sqls executed by sp2 in slow log