MySQL Bugs: #58053: rpl_seconds_behind_master fails mysqltest: At line 66

Bug #58053	rpl_seconds_behind_master fails mysqltest: At line 66
Submitted:	8 Nov 2010 14:32	Modified:	2 Oct 2012 9:52
Reporter:	Andrei Elkin	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.6	OS:	Any
Assigned to:	Luis Soares	CPU Architecture:	Any
Triage:	Triaged: D2 (Serious)

Description:
The test is used to fail. Querying PB2 for it gets e.g:

https://central.sun.net/http://pb2.norway.sun.com/?template=mysql_show_test_failure&test_f...

rpl.rpl_seconds_behind_master 'stmt'     [ fail ]
        Test ended at 2010-10-25 17:19:07

CURRENT_TEST: rpl.rpl_seconds_behind_master
mysqltest: At line 66: 

The result from queries just before the failure was:
< snip >

**** SHOW PROCESSLIST on master ****
SHOW PROCESSLIST;
Id	User	Host	db	Command	Time	State	Info
2	root	localhost	test	Sleep	4		NULL
3	root	localhost:40750	test	Query	0	NULL	SHOW PROCESSLIST
4	root	localhost:40751	test	Sleep	4		NULL
6	root	localhost:40755	NULL	Binlog Dump	0	Master has sent all binlog to slave; waiting for binlog to be updated	NULL

**** SHOW BINLOG EVENTS on master ****
SHOW BINLOG EVENTS IN 'master-bin.000001';
Log_name	Pos	Event_type	Server_id	End_log_pos	Info
master-bin.000001	4	Format_desc	1	107	Server ver: 5.6.1-m4-gcov-debug-log, Binlog ver: 4
master-bin.000001	107	Query	1	174	BEGIN
master-bin.000001	174	Query	1	423	use `mtr`; INSERT INTO test_suppressions (pattern) VALUES ( NAME_CONST('pattern',_latin1'Unsafe statement binlogged in statement format since BINLOG_FORMAT = STATEMENT' COLLATE 'latin1_swedish_ci'))
master-bin.000001	423	Query	1	491	COMMIT
master-bin.000001	491	Query	1	578	use `test`; create table t1 (f1 int)
master-bin.000001	578	Query	1	646	BEGIN
master-bin.000001	646	Query	1	734	use `test`; insert into t1 values (1)
master-bin.000001	734	Query	1	803	COMMIT

More results from queries before failure can be found in /export/home3/pb2/build/sb_2-None-1288009322.12/mysql-trunk-merge-gcov/mysql-test/var/log/rpl_seconds_behind_master.log

 - saving '/export/home3/pb2/build/sb_2-None-1288009322.12/mysql-trunk-merge-gcov/mysql-test/var/log/rpl.rpl_seconds_behind_master-stmt/' to '/export/home3/pb2/build/sb_2-None-1288009322.12/mysql-trunk-merge-gcov/mysql-test/var/log/rpl.rpl_seconds_behind_master-stmt/'

Retrying test, attempt(2/3)...

How to repeat:
See the description, query PB2 failure database.

This has been failing sporadically for some time now. I have observed these
failures in the following trees:

- mysql-next-mr-opt-backporting
- mysql-next-mr-bugfixing
- mysql-next-mr-wl4034
- mysql-trunk-merge
- mysql-next-mr-wl4896
- daily-trunk-bugfixing
- mysql-next-mr-wl2540

Another interesting fact is that rpl_seconds_behind_master failures happened
only when binlog_format=statement.

My initial suspicions are that, either:

  1. assertions in the test that depend on timings are bad
  2. or, that Query_log_event::exec_time may have unexpected value (eg, it
     was not properly initialized), causing seconds_behind_master to show 
     smaller value than it should. See this snippet on rpl_slave.cc:

    if (!(ev->is_artificial_event() || ev->is_relay_log_event() ||
          (ev->when == 0) || ev->get_type_code() == FORMAT_DESCRIPTION_EVENT))
    {    
      rli->last_master_timestamp= ev->when + (time_t) ev->exec_time;
      DBUG_ASSERT(rli->last_master_timestamp >= 0);
    }    

Nonetheless, these are just hints, need further analysis.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/124843

3204 Luis Soares	2010-11-24
      BUG#58053: rpl_seconds_behind_master fails mysqltest: At line 66
      
      Made test case experimental.

Pushed into mysql-trunk 5.6.1-m5 (revid:alexander.nozdrin@oracle.com-20101129111021-874if2qsp0i8d5ze) (version source revid:alexander.nozdrin@oracle.com-20101129111021-874if2qsp0i8d5ze) (merge vers: 5.6.1-m5) (pib:23)

Fixed in 5.6.8.

Closed.