Bug #103943 Semi-Replication Rotate Binlog Leads To Increased Response
Submitted: 8 Jun 11:42 Modified: 10 Jun 1:17
Reporter: chao gao Email Updates:
Status: Open Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.7.25-5.7.33 OS:CentOS (7.6)
Assigned to: MySQL Verification Team CPU Architecture:x86 (64)

[8 Jun 11:42] chao gao
Description:
replication type:M--->S(semi-sync)
version:5.7.25-5.7.33 
max_binlog_size:1G
slave_parallel_type:logical_clock
relay_log_purge:ON
long_query_time:0.1
repl_semi_sync_master_wait_point:after_sync
repl_semi_sync_master_wait_for_slave_count:1
repl_semi_sync_master_wait_no_slave:on
repl_semi_sync_master_timeout=999999999
repl_semi_sync_master_enabled=on
repl_semi_sync_slave_enabled=on

wait_time(master wait slave ack ) will be greater than 200ms when the master rotate binlog.

How to repeat:
1.modify code
file:semisync_master.cc
wait_time = getWaitTime(start_ts);
sql_print_information("ack time is %llu", wait_time);  /*add by gaochao*/
make && make install

2.run sysbench until master rotate binlog,Observe the sysbench response and error log、slow log
[8 Jun 11:49] chao gao
maybe this reason?
Replication: The value returned by a SHOW SLAVE STATUS statement for the total combined size of all existing relay log files (Relay_Log_Space) could become much larger than the actual disk space used by the relay log files. The I/O thread did not lock the variable while it updated the value, so the SQL thread could automatically delete a relay log file and write a reduced value before the I/O thread finished updating the value. The I/O thread then wrote its original size calculation, ignoring the SQL thread's update and so adding back the space for the deleted file. The Relay_Log_Space value is now locked during updates to prevent concurrent updates and ensure an accurate calculation. (Bug #26997096, Bug #87832)

5.7.24:rli->relay_log.harvest_bytes_written(&rli->log_space_total);
5.7.25:rli->relay_log.harvest_bytes_written(rli, true/*need_log_space_lock=true*/);

when i modify 5.7.25 true to false the Response is ok!!!
[9 Jun 13:21] MySQL Verification Team
Hi,

With 5.7.24 you don't have this problem? only with 5.7.25+ ?

thanks
[10 Jun 1:13] chao gao
YES,5.7.24 is ok.

This step is debug mysql5.7.32:
1.sql thread get the log_space_lock
......
2.mysql_file_delete(key_file_binlog, log_info.log_file_name, MYF(0)) function delete the relay_log file
......
3.sql thread release the log_space_lock

io thread can't get the log_space_lock from 1 to 3 and can't response ack to master
[10 Jun 1:15] chao gao
5.7.24 is ok,this problem from 5.7.25 to newest
[10 Jun 1:17] chao gao
I suggest release lock first then delete the relay_log file