Bug #111180 binlog rotate will cause query missing in slow log
Submitted: 29 May 2023 6:19 Modified: 29 May 2023 12:10
Reporter: nanzhou lin Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.7*, 5.7.42 OS:Any
Assigned to: CPU Architecture:Any

[29 May 2023 6:19] nanzhou lin
Description:
if sql produce binlog over max_binlog_size , it will save gtids of last binlog into table and utime_after_clock will be updated cause sql missing in sql slow log. such as one update sql execute 10s, the long_query_time value is 1, but this sql not in slow slog.

How to repeat:
--source include/not_valgrind.inc
--source include/have_binlog_format_row.inc
--source include/have_debug.inc
--source include/not_embedded.inc
--echo #############################################################
--echo #                 Test preparation                          #
--echo #############################################################
create table t1(id int, name varchar(20));
set global max_binlog_size = 4096;
set global slow_query_log= ON;
set global log_output='table';
set global long_query_time=1;
show variables like '%long%';

connect (con1,localhost,root,,);
--echo # Switch to connection con1
connection con1;
show variables like '%long%';
delimiter $$;
create procedure insert_test(in max_num int(10))
begin
declare i int default 0;

set autocommit=0;
repeat
set i=i+1;
insert into t1 (id) values(i);
until i=max_num
end repeat;
commit;
end $$

delimiter ;$$
call insert_test(100000);
set autocommit=1;

update t1 set name = 'test202305290';

select * from mysql.slow_log;

set global max_binlog_size = 1073741824;

update t1 set name = 'test202305291';
select * from mysql.slow_log;

# we find the sql 'update t1 set name = 'test202305290';' is not in slow log, but another sql 'update t1 set name = 'test202305291';' in slow log.
[29 May 2023 8:33] MySQL Verification Team
Hello nanzhou lin,

Thank you for the report and test case.
I couldn't reproduce with 5.7.42 and 8.0.33 builds. Could you please try 8.0.33 and confirm if you are still seeing the issue? Thank you.

- 8.0.33
 ./mtr bug111180 --debug-server --nocheck-testcases
Logging: ./mtr  bug111180 --debug-server --nocheck-testcases
MySQL Version 8.0.33
Checking supported features
 - Binaries are debug compiled
Using 'all' suites
Collecting tests
Checking leftover processes
Removing old var directory
 - WARNING: Using the 'mysql-test/var' symlink
Creating var directory '/export/home/tmp/ushastry/mysql-8.0.33/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
#############################################################
#                 Test preparation                          #
#############################################################
create table t1(id int, name varchar(20));
set global max_binlog_size = 4096;
set global slow_query_log= ON;
set global log_output='table';
set global long_query_time=1;
show variables like '%long%';
Variable_name   Value
long_query_time 10.000000
performance_schema_events_stages_history_long_size      1000
performance_schema_events_statements_history_long_size  1000
performance_schema_events_transactions_history_long_size        1000
performance_schema_events_waits_history_long_size       10000
# Switch to connection con1
show variables like '%long%';
Variable_name   Value
long_query_time 1.000000
performance_schema_events_stages_history_long_size      1000
performance_schema_events_statements_history_long_size  1000
performance_schema_events_transactions_history_long_size        1000
performance_schema_events_waits_history_long_size       10000
create procedure insert_test(in max_num int(10))
begin
declare i int default 0;
set autocommit=0;
repeat
set i=i+1;
insert into t1 (id) values(i);
until i=max_num
end repeat;
commit;
end $$
Warnings:
Warning 1681    Integer display width is deprecated and will be removed in a future release.
call insert_test(100000);
set autocommit=1;
update t1 set name = 'test202305290';
select * from mysql.slow_log;
start_time      user_host       query_time      lock_time       rows_sent       rows_examined   db      last_insert_id  insert_id       server_id       sql_text        thread_id
2023-05-29 11:00:57.667172      root[root] @ localhost []       00:00:28.136389 00:00:00.000007 0       0       test    0       0       1       call insert_test(100000)        9
2023-05-29 11:01:34.635214      root[root] @ localhost []       00:00:36.964532 00:00:00.000006 0       100000  test    0       0       1       update t1 set name = 'test202305290'    9
set global max_binlog_size = 1073741824;
update t1 set name = 'test202305291';
select * from mysql.slow_log;
start_time      user_host       query_time      lock_time       rows_sent       rows_examined   db      last_insert_id  insert_id       server_id       sql_text        thread_id
2023-05-29 11:00:57.667172      root[root] @ localhost []       00:00:28.136389 00:00:00.000007 0       0       test    0       0       1       call insert_test(100000)        9
2023-05-29 11:01:34.635214      root[root] @ localhost []       00:00:36.964532 00:00:00.000006 0       100000  test    0       0       1       update t1 set name = 'test202305290'    9
2023-05-29 11:01:47.846700      root[root] @ localhost []       00:00:13.210822 00:00:00.000007 0       100000  test    0       0       1       update t1 set name = 'test202305291'    9
[ 50%] main.bug111180                            [ pass ]  78386
[100%] shutdown_report                           [ pass ]
------------------------------------------------------------------------------

- 5.7.42
./mtr bug111180 --debug-server --nocheck-testcases
Logging: ./mtr  bug111180 --debug-server --nocheck-testcases
MySQL Version 5.7.42
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/export/home/tmp/ushastry/mysql-5.7.42/mysql-test/var'...
Installing system database...
Using parallel: 1

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
#############################################################
#                 Test preparation                          #
#############################################################
create table t1(id int, name varchar(20));
set global max_binlog_size = 4096;
set global slow_query_log= ON;
set global log_output='table';
set global long_query_time=1;
show variables like '%long%';
Variable_name   Value
long_query_time 10.000000
performance_schema_events_stages_history_long_size      1000
performance_schema_events_statements_history_long_size  1000
performance_schema_events_transactions_history_long_size        1000
performance_schema_events_waits_history_long_size       10000
# Switch to connection con1
show variables like '%long%';
Variable_name   Value
long_query_time 1.000000
performance_schema_events_stages_history_long_size      1000
performance_schema_events_statements_history_long_size  1000
performance_schema_events_transactions_history_long_size        1000
performance_schema_events_waits_history_long_size       10000
create procedure insert_test(in max_num int(10))
begin
declare i int default 0;
set autocommit=0;
repeat
set i=i+1;
insert into t1 (id) values(i);
until i=max_num
end repeat;
commit;
end $$
call insert_test(100000);
set autocommit=1;
update t1 set name = 'test202305290';
select * from mysql.slow_log;
start_time      user_host       query_time      lock_time       rows_sent       rows_examined   db      last_insert_id  insert_id       server_id       sql_text        thread_id
2023-05-29 11:29:28.740865      root[root] @ localhost []       00:00:23.305604 00:00:00.000117 0       0       test    0       0       1       call insert_test(100000)        3
2023-05-29 11:29:56.829732      root[root] @ localhost []       00:00:28.084774 00:00:00.000183 0       100000  test    0       0       1       update t1 set name = 'test202305290'    3
set global max_binlog_size = 1073741824;
update t1 set name = 'test202305291';
select * from mysql.slow_log;
start_time      user_host       query_time      lock_time       rows_sent       rows_examined   db      last_insert_id  insert_id       server_id       sql_text        thread_id
2023-05-29 11:29:28.740865      root[root] @ localhost []       00:00:23.305604 00:00:00.000117 0       0       test    0       0       1       call insert_test(100000)        3
2023-05-29 11:29:56.829732      root[root] @ localhost []       00:00:28.084774 00:00:00.000183 0       100000  test    0       0       1       update t1 set name = 'test202305290'    3
2023-05-29 11:30:05.576754      root[root] @ localhost []       00:00:08.746219 00:00:00.000181 0       100000  test    0       0       1       update t1 set name = 'test202305291'    3
[ 50%] main.bug111180                           [ pass ]  60177
[100%] shutdown_report                          [ pass ]

regards,
Umesh
[29 May 2023 12:00] nanzhou lin
it need set gtid_mode=on;
please try run this test again:

--source include/not_valgrind.inc
--source include/have_binlog_format_row.inc
--source include/have_debug.inc
--source include/not_embedded.inc
--echo #############################################################
--echo #                 Test preparation                          #
--echo #############################################################
create table t1(id int, name varchar(20));
set global max_binlog_size = 4096;
set global slow_query_log= ON;
set global log_output='table';
set global long_query_time=1;
show variables like '%long_query_time%';
show variables like '%gtid_mode%';

connect (con1,localhost,root,,);
--echo # Switch to connection con1
connection con1;
show variables like '%long_query_time%';
delimiter $$;
create procedure insert_test(in max_num int(10))
begin
declare i int default 0;

set autocommit=0;
repeat
set i=i+1;
insert into t1 (id) values(i);
until i=max_num
end repeat;
commit;
end $$

delimiter ;$$
call insert_test(100000);
set autocommit=1;

update t1 set name = 'test202305290';

select * from mysql.slow_log;

set global max_binlog_size = 1073741824;

update t1 set name = 'test202305291';
select * from mysql.slow_log;

test results:
MySQL Version 5.7.42
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
 - adding combinations for binlog_gtid
Checking leftover processes...
Removing old var directory...
Creating var directory '/u01/lnz/mysql57_42/mysql-test/var'...
Installing system database...
Using parallel: 1

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
[ 25%] binlog_gtid.2 'mix'                      [ skipped ]  Doesn't support --binlog-format='mixed'
#############################################################
#                 Test preparation                          #
#############################################################
create table t1(id int, name varchar(20));
set global max_binlog_size = 4096;
set global slow_query_log= ON;
set global log_output='table';
set global long_query_time=1;
show variables like '%long_query_time%';
Variable_name	Value
long_query_time	10.000000
show variables like '%gtid_mode%';
Variable_name	Value
gtid_mode	ON
# Switch to connection con1
show variables like '%long_query_time%';
Variable_name	Value
long_query_time	1.000000
create procedure insert_test(in max_num int(10))
begin
declare i int default 0;
set autocommit=0;
repeat
set i=i+1;
insert into t1 (id) values(i);
until i=max_num
end repeat;
commit;
end $$
call insert_test(100000);
set autocommit=1;
update t1 set name = 'test202305290';
select * from mysql.slow_log;
start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id
2023-05-29 14:57:17.211511	root[root] @ localhost []	00:00:19.992521	00:00:00.000115	0	0	test	0	0	1	call insert_test(100000)	4
set global max_binlog_size = 1073741824;
update t1 set name = 'test202305291';
select * from mysql.slow_log;
start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text	thread_id
2023-05-29 14:57:17.211511	root[root] @ localhost []	00:00:19.992521	00:00:00.000115	0	0	test	0	0	1	call insert_test(100000)	4
2023-05-29 14:57:49.391855	root[root] @ localhost []	00:00:07.752099	00:00:00.000180	0	100000	test	0	0	1	update t1 set name = 'test202305291'	4
[29 May 2023 12:02] MySQL Verification Team
Thank you for the feedback.
Let me re-run and get back to you if anything further needed.

regards,
Umesh
[29 May 2023 12:10] MySQL Verification Team
- 5.7.42 - affected

 ./mtr bug111180 --debug-server --nocheck-testcases --mysqld='--gtid_mode=ON' --mysqld='--log-bin' --mysqld='--log-slave-updates' --mysqld='--enforce-gtid-consistency' --mysqld='--server-id=1'
Logging: ./mtr  bug111180 --debug-server --nocheck-testcases --mysqld=--gtid_mode=ON --mysqld=--log-bin --mysqld=--log-slave-updates --mysqld=--enforce-gtid-consistency --mysqld=--server-id=1
MySQL Version 5.7.42
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/export/home/tmp/ushastry/mysql-5.7.42/mysql-test/var'...
Installing system database...
Using parallel: 1

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
#############################################################
#                 Test preparation                          #
#############################################################
create table t1(id int, name varchar(20));
set global max_binlog_size = 4096;
set global slow_query_log= ON;
set global log_output='table';
set global long_query_time=1;
show variables like '%long%';
Variable_name   Value
long_query_time 10.000000
performance_schema_events_stages_history_long_size      1000
performance_schema_events_statements_history_long_size  1000
performance_schema_events_transactions_history_long_size        1000
performance_schema_events_waits_history_long_size       10000
# Switch to connection con1
show variables like '%long%';
Variable_name   Value
long_query_time 1.000000
performance_schema_events_stages_history_long_size      1000
performance_schema_events_statements_history_long_size  1000
performance_schema_events_transactions_history_long_size        1000
performance_schema_events_waits_history_long_size       10000
create procedure insert_test(in max_num int(10))
begin
declare i int default 0;
set autocommit=0;
repeat
set i=i+1;
insert into t1 (id) values(i);
until i=max_num
end repeat;
commit;
end $$
call insert_test(100000);
set autocommit=1;
update t1 set name = 'test202305290';
select * from mysql.slow_log;
start_time      user_host       query_time      lock_time       rows_sent       rows_examined   db      last_insert_id  insert_id       server_id       sql_text        thread_id
2023-05-29 15:06:47.243112      root[root] @ localhost []       00:00:23.332690 00:00:00.000124 0       0       test    0       0       1       call insert_test(100000)        3
set global max_binlog_size = 1073741824;
update t1 set name = 'test202305291';
select * from mysql.slow_log;
start_time      user_host       query_time      lock_time       rows_sent       rows_examined   db      last_insert_id  insert_id       server_id       sql_text        thread_id
2023-05-29 15:06:47.243112      root[root] @ localhost []       00:00:23.332690 00:00:00.000124 0       0       test    0       0       1       call insert_test(100000)        3
2023-05-29 15:07:24.300751      root[root] @ localhost []       00:00:08.672039 00:00:00.000183 0       100000  test    0       0       1       update t1 set name = 'test202305291'    3
[ 50%] main.bug111180                           [ pass ]  60419
[100%] shutdown_report                          [ pass ]
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 60.419 of 67 seconds executing testcases

Completed: All 2 tests were successful.
[29 May 2023 12:13] MySQL Verification Team
- 8.0.33 seems to be OK

 ./mtr bug111180 --debug-server --nocheck-testcases --mysqld='--gtid_mode=ON' --mysqld='--log-bin' --mysqld='--log-slave-updates' --mysqld='--enforce-gtid-consistency' --mysqld='--server-id=1'
Logging: ./mtr  bug111180 --debug-server --nocheck-testcases --mysqld=--gtid_mode=ON --mysqld=--log-bin --mysqld=--log-slave-updates --mysqld=--enforce-gtid-consistency --mysqld=--server-id=1
MySQL Version 8.0.33
Checking supported features
 - Binaries are debug compiled
Using 'all' suites
Collecting tests
Checking leftover processes
Removing old var directory
 - WARNING: Using the 'mysql-test/var' symlink
Creating var directory '/export/home/tmp/ushastry/mysql-8.0.33/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
#############################################################
#                 Test preparation                          #
#############################################################
create table t1(id int, name varchar(20));
set global max_binlog_size = 4096;
set global slow_query_log= ON;
set global log_output='table';
set global long_query_time=1;
show variables like '%long%';
Variable_name   Value
long_query_time 10.000000
performance_schema_events_stages_history_long_size      1000
performance_schema_events_statements_history_long_size  1000
performance_schema_events_transactions_history_long_size        1000
performance_schema_events_waits_history_long_size       10000
# Switch to connection con1
show variables like '%long%';
Variable_name   Value
long_query_time 1.000000
performance_schema_events_stages_history_long_size      1000
performance_schema_events_statements_history_long_size  1000
performance_schema_events_transactions_history_long_size        1000
performance_schema_events_waits_history_long_size       10000
create procedure insert_test(in max_num int(10))
begin
declare i int default 0;
set autocommit=0;
repeat
set i=i+1;
insert into t1 (id) values(i);
until i=max_num
end repeat;
commit;
end $$
Warnings:
Warning 1681    Integer display width is deprecated and will be removed in a future release.
call insert_test(100000);
set autocommit=1;
update t1 set name = 'test202305290';
select * from mysql.slow_log;
start_time      user_host       query_time      lock_time       rows_sent       rows_examined   db      last_insert_id  insert_id       server_id       sql_text        thread_id
2023-05-29 15:11:02.710098      root[root] @ localhost []       00:00:27.749990 00:00:00.000007 0       0       test    0       0       1       call insert_test(100000)        9
2023-05-29 15:11:39.699036      root[root] @ localhost []       00:00:36.985884 00:00:00.000010 0       100000  test    0       0       1       update t1 set name = 'test202305290'    9
set global max_binlog_size = 1073741824;
update t1 set name = 'test202305291';
select * from mysql.slow_log;
start_time      user_host       query_time      lock_time       rows_sent       rows_examined   db      last_insert_id  insert_id       server_id       sql_text        thread_id
2023-05-29 15:11:02.710098      root[root] @ localhost []       00:00:27.749990 00:00:00.000007 0       0       test    0       0       1       call insert_test(100000)        9
2023-05-29 15:11:39.699036      root[root] @ localhost []       00:00:36.985884 00:00:00.000010 0       100000  test    0       0       1       update t1 set name = 'test202305290'    9
2023-05-29 15:11:52.928097      root[root] @ localhost []       00:00:13.228370 00:00:00.000005 0       100000  test    0       0       1       update t1 set name = 'test202305291'    9
[ 50%] main.bug111180                            [ pass ]  78042
[100%] shutdown_report                           [ pass ]
------------------------------------------------------------------------------
The servers were restarted 0 times
The servers were reinitialized 0 times
Spent 78.042 of 96 seconds executing testcases

Completed: All 2 tests were successful.