| 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: | |
| Category: | MySQL Server: Logging | Severity: | S3 (Non-critical) |
| Version: | 5.7*, 5.7.42, 5.7.44 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[29 May 2023 6:19]
nanzhou lin
[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.
