Bug #71083 updating mysql.slave_relay_log_info depends on sync_relay_log_info
Submitted: 5 Dec 2013 3:59 Modified: 11 Dec 2013 2:18
Reporter: Tsubasa Tanaka (OCA) Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.6.15 OS:Any
Assigned to: CPU Architecture:Any

[5 Dec 2013 3:59] Tsubasa Tanaka
Description:
Docs says "The table is updated after each transaction(in Transactional Table)" when relay_log_info_repository= TABLE.

http://dev.mysql.com/doc/refman/5.6/en/replication-options-slave.html#sysvar_sync_relay_lo...

But the truth, updating mysql.slave_relay_log_info depends on value of sync_relay_log_info.

This behavier is different from Docs and this can't get to be crash-safe replication even if setting relay_log_recovery= 1.

See also, http://bugs.mysql.com/bug.php?id=69135 and http://bugs.mysql.com/bug.php?id=70784

How to repeat:
mysql> SELECT @@relay_log_info_repository;
+-----------------------------+
| @@relay_log_info_repository |
+-----------------------------+
| TABLE                       |
+-----------------------------+
1 row in set (0.00 sec)

mysql> SELECT @@sync_relay_log_info;
+-----------------------+
| @@sync_relay_log_info |
+-----------------------+
|                 10000 |
+-----------------------+
1 row in set (0.01 sec)

mysql> show create table mysql.slave_relay_log_info\G
*************************** 1. row ***************************
       Table: slave_relay_log_info
Create Table: CREATE TABLE `slave_relay_log_info` (
  `Number_of_lines` int(10) unsigned NOT NULL COMMENT 'Number of lines in the file or rows in the table. Used to version table definitions.',
  `Relay_log_name` text CHARACTER SET utf8 COLLATE utf8_bin NOT NULL COMMENT 'The name of the current relay log file.',
  `Relay_log_pos` bigint(20) unsigned NOT NULL COMMENT 'The relay log position of the last executed event.',
  `Master_log_name` text CHARACTER SET utf8 COLLATE utf8_bin NOT NULL COMMENT 'The name of the master binary log file from which the events in the relay log file were read.',
  `Master_log_pos` bigint(20) unsigned NOT NULL COMMENT 'The master log position of the last executed event.',
  `Sql_delay` int(11) NOT NULL COMMENT 'The number of seconds that the slave must lag behind the master.',
  `Number_of_workers` int(10) unsigned NOT NULL,
  `Id` int(10) unsigned NOT NULL COMMENT 'Internal Id that uniquely identifies this record.',
  PRIMARY KEY (`Id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 STATS_PERSISTENT=0 COMMENT='Relay Log Information'
1 row in set (0.01 sec)

=======
$ gdb -p `pidof mysqld`
(gdb) b Rpl_info_table::do_flush_info
Breakpoint 1 at 0xa42df1: file /home/ttanaka/mysql-5.6.15/sql/rpl_info_table.cc, line 139.
(gdb) c
Continuing.
[Switching to Thread 0x7fb93875b700 (LWP 30823)]

Breakpoint 1, Rpl_info_table::do_flush_info (this=0x47b3590, force=false)
    at /home/ttanaka/mysql-5.6.15/sql/rpl_info_table.cc:139
139       int error= 1;
(gdb) list
134       DBUG_RETURN(error);
135     }
136
137     int Rpl_info_table::do_flush_info(const bool force)
138     {
139       int error= 1;
140       enum enum_return_id res= FOUND_ID;
141       TABLE *table= NULL;
142       ulong saved_mode;
143       Open_tables_backup backup;
(gdb) n
140       enum enum_return_id res= FOUND_ID;
(gdb) p sync_period
$2 = 10000
(gdb) p force
$3 = false
(gdb) n
141       TABLE *table= NULL;
(gdb)
143       Open_tables_backup backup;
(gdb)
145       DBUG_ENTER("Rpl_info_table::do_flush_info");
(gdb)
147       if (!(force || (sync_period &&
(gdb) list
142       ulong saved_mode;
143       Open_tables_backup backup;
144
145       DBUG_ENTER("Rpl_info_table::do_flush_info");
146
147       if (!(force || (sync_period &&
148           ++(sync_counter) >= sync_period)))
149         DBUG_RETURN(0);
150
151       THD *thd= access->create_thd();
(gdb) p sync_counter
$4 = 2
(gdb) n
149         DBUG_RETURN(0);
(gdb)
243     }

Each calling to Rpl_info_table::do_flush_info, that checks sync_counter grater equal than sync_period.
This is unnecessary.

Suggested fix:
*** sql/rpl_info_table.cc.orig  2013-11-18 03:02:54.000000000 +0900
--- sql/rpl_info_table.cc       2013-12-05 12:58:02.466800795 +0900
***************
*** 144,151 ****

    DBUG_ENTER("Rpl_info_table::do_flush_info");

!   if (!(force || (sync_period &&
!       ++(sync_counter) >= sync_period)))
      DBUG_RETURN(0);

    THD *thd= access->create_thd();
--- 144,150 ----

    DBUG_ENTER("Rpl_info_table::do_flush_info");

!   if (!(force || do_update_is_transactional()))
      DBUG_RETURN(0);

    THD *thd= access->create_thd();

But do_update_is_transactional always returns FALSE in my environment.
Is it correct?
[10 Dec 2013 18:21] MySQL Verification Team
Actually, the fact that is_transactional() returns FALSE, it means that TABLE option has either not be activated or the table is not InnoDB. Could be that InnoDB SE is not started ?? 

Parameter `force` in ::do_flush_info() method is ALWAYS true for the transactional tables. You can debug is_transactional()  and check for yourself.

Anyway check for the type of file that relay.info is stored in.
[11 Dec 2013 2:18] Tsubasa Tanaka
Hello, Sinisa.

I recognized my misunderstood of "(in Transactional Table)".
I feel that means "When mysql.slave_relay_log_info is Transactional Table", but in fact, that means "When both of master's updating table and slave's updating table are Transactional Table", even if mysql.slave_relay_log_info uses MyISAM SE.

Master MyISAM-> Slave MyISAM: depends on sync_relay_log_info
Master MyISAM-> Slave InnoDB: depends on sync_relay_log_info
Master InnoDB-> Slave MyISAM: depends on sync_relay_log_info
Master InnoDB-> Slave InnoDB: updated after each transaction

Indeed, this is "Not a Bug". I'm sorry and thank you for your time.