MySQL Bugs: #47972: Change in MBR algorithm causes replication performance degradation

Bug #47972	Change in MBR algorithm causes replication performance degradation
Submitted:	10 Oct 2009 21:36	Modified:	28 Jul 2011 9:25
Reporter:	Elena Stepanova	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.1.40	OS:	Any
Assigned to:	Assigned Account	CPU Architecture:	Any

Description:
Up to and including 5.1.39, if a server was run with MIXED binlog format, UPDATE statements in the test case provided in 'How to repeat' section were logged in STATEMENT format. In 5.1.40 they are logged in ROW format. I assume that's the reason why with the same scenario it takes much longer in 5.1.40 until the slave synchronizes with the master.

How much longer, depends on the platform/machine. 
Counting the time after all updates on master are done and before slave catches up with the master, for me it took ~20 seconds on Linux, ~60 seconds on Windows and Solaris x86, and many minutes on Solaris Sparc (you might want to reduce $run value on the 4th line if your test takes too long).

With 5.1.39, it takes about a second on all the platforms/machines I used.

How to repeat:
# The test creates a table with a trigger on update writing into another table, 
# populates the 1st table with 4096 records, and then runs $run number of
# updates, a few hundreds rows each.
# Then it waits until the slave synchronizes with the master, prints rough 
# time measurements, and exits.

# t/rpl_mbr_slow.test

source include/master-slave.inc;
source include/have_binlog_format_mixed.inc;

let $run=100;

--disable_query_log
--disable_result_log

USE test;

--disable_warnings
DROP TABLE IF EXISTS tb1;
--enable_warnings

CREATE TABLE `tb1` (
  `f1` int(11) DEFAULT NULL,
  `f2` char(15) DEFAULT NULL,
  `f3` decimal(5,3) DEFAULT NULL,
  `f4` datetime DEFAULT NULL
) ENGINE=MyISAM;

CREATE TABLE `tb1_logs` (
  `i1` int(11) NOT NULL AUTO_INCREMENT,
  `dt1` datetime NOT NULL,
  `entry_dsc` char(100) DEFAULT NULL,
  `f4` int(11) DEFAULT NULL,
  PRIMARY KEY (`i1`)
) ENGINE=MyISAM;

INSERT INTO tb1 VALUES ( round(rand()*15)+1, 'test', round(rand()*15,3), now() );
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;
INSERT INTO tb1 SELECT round(rand()*15)+1, 'test', round(rand()*15,3), now() FROM tb1;

Create trigger trg after update on tb1 for each row
   insert into tb1_logs (dt1, entry_dsc, f4)
   values (now(), concat('Update row ', old.f1,' ', old.f2, '->',
           new.f2, ' ', old.f3, '->', new.f3, ' (tb1)'), new.f1);

sync_slave_with_master;

connection master;

set @master_job_started = now();
while ($run)
{
        let $f1 = `SELECT round(rand()*15)+1`;
        eval update tb1
                set f2=concat('updated'), f3=f3+1
                where f1=$f1;
        dec $run;
}

set @master_job_finished = now();
sync_slave_with_master;
connection master;  # in case time on master and slave is different

let $time_for_sync = `select timediff(now(),@master_job_finished)`;
let $time_for_master_job = `select timediff(@master_job_finished,@master_job_started)`;
echo #
########################################################
#  It took $time_for_master_job for master to do the job           #
#  It took $time_for_sync for slave to catch up with master  #
########################################################;

# end of t/rpl_mbr_slow.test

# run as 
perl ./mysql-test-run.pl --mysqld=--binlog_format=mixed rpl_mbr_slow

Thank you for the report.

Verified as described.

5.1.38:

########################################################
#  It took 00:00:01 for master to do the job           #
#  It took 00:00:00 for slave to catch up with master  #
########################################################

Current bzr:

########################################################
#  It took 00:00:09 for master to do the job           #
#  It took 00:01:20 for slave to catch up with master  #
########################################################

The change was apparently intentional (bug#45677).

See Worklog#5597

Running the test on Ubuntu 10.10, I got result:
########################################################
#  It took 00:00:22 for master to do the job           #
#  It took 00:01:59 for slave to catch up with master  #
########################################################

It can improve the performance by adding a primary key.
After added a primary key(f1, f3, f4) on tb1, the testing result is:
########################################################
#  It took 00:01:16 for master to do the job           #
#  It took 00:00:08 for slave to catch up with master  #
########################################################

Duplicate of BUG#53375.