チョットワカル Row-Based Replication・その１

2019/10/24

sejima

こんにちわ。せじまです。珍しく replication の話をします。しかも、複数回に渡って続きます。連載です。

はじめに

「詳しくは後日、ソースコード交えつつ別のかたちでご紹介したいと思います。」と言っていた件です。

Row-Based Replication の話をします。

昨年の8月頃、「そろそろ、SBRからRBRに移行して良い時期かなぁ、しないと将来めんどくさいかなぁ」「でも、 SET GLOBAL で binlog_format 変更できないと、手間かかってしょうがないなぁ」「じゃソースコード読むかぁ」ということで、MySQL の Replication はそんなに得意分野でもないので、他の仕事の合間にちょくちょく調べて、社内文書にまとめてました。

公開しても良いのでは、と思った内容なので、一部修正しつつ、お届けします。

はじめに断っておきますと、この話は長いです。2-3回では終わらないと思いますので、じっくり腰を据えて読んで頂くのがよろしいかと思います。

解説

前提：そもそも binary log による replication とは

まずは前提として、このあたりのスライドを読んでもらえると、MYSQL_BIN_LOG::ordered_commit() あたりの実装がわかります。

slave の SQL_Thread（最近は Applyer thread ともいいます。 binlog_format=row が導入されたことによって、 SQL だけではなく SQLCOM_BINLOG_BASE64_EVENT なども実行するようになったってことでしょう）は歴史的にシングルスレッドです。
よって、SQL_Thread がシングルスレッドだった時代は、 master は複数のスレッドで同時にトランザクションを実行できましたが、 slave は一つのSQL_Threadだけで一個ずつトランザクションを実行するしかなかったのです。
そうであるならば、master が複数のスレッドで実行していた複数のトランザクションを、シリアライズして binary log に書いて、トランザクション一個一個を SQL_Thread で replay するしかないわけです。

というわけで、MYSQL_BIN_LOG::ordered_commit() は、トランザクションが commit された順番で、各トランザクションを BEGIN ～ COMMIT で挟んで、シリアライズされた状態で binary log に書き出しています。
InnoDB の Isolation Level 的に考えると、 READ UNCOMMITTED でない限り、他のスレッドはCOMMIT されてないトランザクションの結果を参照できません。
よって、 master の InnoDB で同時に複数のトランザクション実行されていたとしても、COMMIT されない限り、そのトランザクションによる更新結果を他のスレッドは参照できないので、 COMMIT の順が保たれていれば、その binary log でレプリケーションしている slave で見えている結果は、（非同期なので遅延しているが）整合性が担保できるはずである、と。そういうわけでしょう。

（master と slave の状態が異なっている場合、 unsafe statement とかで整合性が崩れてしまうケースもありえるのですが、それについては今回言及しないことにします）

binlog_format=ROW になったとき、binlog event はどの時点で transaction cache に書き出されるのか

MySQL Musings:Binary Log Group Commit in MySQL 5.6 から抜粋すると

As the server executes transactions the server will collect the changes done by the transaction in a per-connection transaction cache. If statement-based replication is used, the statements will be written to the transaction cache, and if row-based replication is used, the actual rows changed will be written to the transaction cache. Once the transaction commits, the transaction cache is written to the binary log as one single block.

ソースコードを読んだほうが早いでしょうから、 MySQL 8.0.12 のソースコードをもとに解説します。

※当時、「ぼちぼちMySQL 8.0のソースコード読んどくかなぁ」と思っていたので、以降の説明は MySQL 8.0.12 が前提となっています。

とりあえず、（UPDATEは読みやすいかなと思ったので） SQLCOM_UPDATE 受けてから binlog_format=row で UPDATE_ROWS_EVENT 書くところまで

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/sql_parse.cc#L3218

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/sql_parse.cc#L3228

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/sql_select.cc#L469

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/sql_select.cc#L554

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/sql_update.cc#L1514

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/sql_update.cc#L265

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/sql_update.cc#L809

        } else {
          /* Non-batched update */
          error =
              table->file->ha_update_row(table->record[1], table->record[0]);
        }
        if (error == 0)
          updated_rows++;

806

807

808

809

810

811

812

} else {

/* Non-batched update */

error =

table->file->ha_update_row(table->record[1], table->record[0]);

}

if (error == 0)

updated_rows++;

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/handler.cc#L7490

handler の中で、 binlog_log_row() で UPDATE_ROWS_EVENT を transaction cache に書いていきます。

  Log_func *log_func = Update_rows_log_event::binlog_row_logging_function;

7493	Log_func *log_func = Update_rows_log_event::binlog_row_logging_function;

  MYSQL_TABLE_IO_WAIT(PSI_TABLE_UPDATE_ROW, active_index, error,
                      { error = update_row(old_data, new_data); })

  if (unlikely(error)) return error;
  if (unlikely((error = binlog_log_row(table, old_data, new_data, log_func))))

7509

7510

7511

7512

7513

MYSQL_TABLE_IO_WAIT(PSI_TABLE_UPDATE_ROW, active_index, error,

{ error = update_row(old_data, new_data); })

if (unlikely(error)) return error;

if (unlikely((error = binlog_log_row(table, old_data, new_data, log_func))))

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/handler.cc#L7513

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/sql_update.cc#L953

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/binlog.cc#L11251

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/binlog.cc#L11277

その query おわったら、 binlog_flush_pending_rows_event() で STMT_END_F 書いて UPDATE_ROWS_EVENT の終わりであることを示します。

  /*
    If we are not in prelocked mode, mysql_unlock_tables() will be
    called after this binlog_query(), so we have to flush the pending
    rows event with the STMT_END_F set to unlock all tables at the
    slave side as well.
    If we are in prelocked mode, the flushing will be done inside the
    top-most close_thread_tables().
  */
  if (this->locked_tables_mode <= LTM_LOCK_TABLES)
    if (int error = binlog_flush_pending_rows_event(true, is_trans))
      DBUG_RETURN(error);

11267

11268

11269

11270

11271

11272

11273

11274

11275

11276

11277

If we are not in prelocked mode, mysql_unlock_tables() will be

called after this binlog_query(), so we have to flush the pending

rows event with the STMT_END_F set to unlock all tables at the

slave side as well.

If we are in prelocked mode, the flushing will be done inside the

top-most close_thread_tables().

if (this->locked_tables_mode <= LTM_LOCK_TABLES)

if (int error = binlog_flush_pending_rows_event(true, is_trans))

DBUG_RETURN(error);

ちなみに、 binlog_format=statement の場合は

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/sql_update.cc#L953

ここで渡してる thd->query() から

      if (thd->binlog_query(THD::ROW_QUERY_TYPE, thd->query().str,
                            thd->query().length, transactional_table, false,
                            false, errcode)) {

953

954

955

if (thd->binlog_query(THD::ROW_QUERY_TYPE, thd->query().str,

thd->query().length, transactional_table, false,

false, errcode)) {

https://github.com/mysql/mysql-server/blob/mysql-8.0.12/sql/binlog.cc#L11344

Query_log_event のinstance生成して mysql_bin_log.write_event() するだけですね。

    case THD::STMT_QUERY_TYPE:
      /*
        The MYSQL_BIN_LOG::write() function will set the STMT_END_F flag and
        flush the pending rows event if necessary.
      */
      {
        Query_log_event qinfo(this, query_arg, query_len, is_trans, direct,
                              suppress_use, errcode);
        /*
          Binlog table maps will be irrelevant after a Query_log_event
          (they are just removed on the slave side) so after the query
          log event is written to the binary log, we pretend that no
          table maps were written.
         */
        int error = mysql_bin_log.write_event(&qinfo);
        binlog_table_maps = 0;
        DBUG_RETURN(error);
      }

11330

11331

11332

11333

11334

11335

11336

11337

11338

11339

11340

11341

11342

11343

11344

11345

11346

11347

case THD::STMT_QUERY_TYPE:

The MYSQL_BIN_LOG::write() function will set the STMT_END_F flag and

flush the pending rows event if necessary.

{

Query_log_event qinfo(this, query_arg, query_len, is_trans, direct,

suppress_use, errcode);

Binlog table maps will be irrelevant after a Query_log_event

(they are just removed on the slave side) so after the query

log event is written to the binary log, we pretend that no

table maps were written.

int error = mysql_bin_log.write_event(&qinfo);

binlog_table_maps = 0;

DBUG_RETURN(error);

}

具体的に確認すると

例えば、MySQL8.0.18 で INSERT で確認してみますと、

mysql>  show create table sejima\G
*************************** 1. row ***************************
       Table: sejima
Create Table: CREATE TABLE `sejima` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `rank` int(11) NOT NULL,
  PRIMARY KEY (`id`)
1 row in set (0.00 sec)

mysql> show create table sejima\G
*************************** 1. row ***************************
       Table: sejima
Create Table: CREATE TABLE `sejima` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `rank` int(11) NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=982865 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)

mysql> show table status like 'sejima'\G
*************************** 1. row ***************************
           Name: sejima
         Engine: InnoDB
        Version: 10
     Row_format: Dynamic
           Rows: 0
 Avg_row_length: 0
    Data_length: 16384
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: 982865
    Create_time: 2019-10-15 11:28:18
    Update_time: NULL
     Check_time: NULL
      Collation: utf8mb4_0900_ai_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)

mysql> show global status like 'InnoDB_R%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| Innodb_row_lock_current_waits | 0     |
| Innodb_row_lock_time          | 0     |
| Innodb_row_lock_time_avg      | 0     |
| Innodb_row_lock_time_max      | 0     |
| Innodb_row_lock_waits         | 0     |
| Innodb_rows_deleted           | 16    |
| Innodb_rows_inserted          | 37    |
| Innodb_rows_read              | 4679  |
| Innodb_rows_updated           | 341   |
+-------------------------------+-------+
9 rows in set (0.00 sec)

mysql> insert into sejima (`rank`) values (3),(4);
Query OK, 2 rows affected (0.02 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> show global status like 'InnoDB_R%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| Innodb_row_lock_current_waits | 0     |
| Innodb_row_lock_time          | 0     |
| Innodb_row_lock_time_avg      | 0     |
| Innodb_row_lock_time_max      | 0     |
| Innodb_row_lock_waits         | 0     |
| Innodb_rows_deleted           | 16    |
| Innodb_rows_inserted          | 39    |
| Innodb_rows_read              | 4679  |
| Innodb_rows_updated           | 341   |
+-------------------------------+-------+
9 rows in set (0.00 sec)

mysql> exit
Bye

mysql> show create table sejima\G

*************************** 1. row ***************************

Table: sejima

Create Table: CREATE TABLE `sejima` (

`id` int(11) NOT NULL AUTO_INCREMENT,

`rank` int(11) NOT NULL,

PRIMARY KEY (`id`)

1 row in set (0.00 sec)

mysql> show create table sejima\G

*************************** 1. row ***************************

Table: sejima

Create Table: CREATE TABLE `sejima` (

`id` int(11) NOT NULL AUTO_INCREMENT,

`rank` int(11) NOT NULL,

PRIMARY KEY (`id`)

) ENGINE=InnoDB AUTO_INCREMENT=982865 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci

1 row in set (0.00 sec)

mysql> show table status like 'sejima'\G

*************************** 1. row ***************************

Name: sejima

Engine: InnoDB

Version: 10

Row_format: Dynamic

Rows: 0

Avg_row_length: 0

Data_length: 16384

Max_data_length: 0

Index_length: 0

Data_free: 0

Auto_increment: 982865

Create_time: 2019-10-15 11:28:18

Update_time: NULL

Check_time: NULL

Collation: utf8mb4_0900_ai_ci

Checksum: NULL

Create_options:

Comment:

1 row in set (0.00 sec)

mysql> show global status like 'InnoDB_R%';

+-------------------------------+-------+

| Variable_name | Value |

+-------------------------------+-------+

| Innodb_row_lock_current_waits | 0 |

| Innodb_row_lock_time | 0 |

| Innodb_row_lock_time_avg | 0 |

| Innodb_row_lock_time_max | 0 |

| Innodb_row_lock_waits | 0 |

| Innodb_rows_deleted | 16 |

| Innodb_rows_inserted | 37 |

| Innodb_rows_read | 4679 |

| Innodb_rows_updated | 341 |

+-------------------------------+-------+

9 rows in set (0.00 sec)

mysql> insert into sejima (`rank`) values (3),(4);

Query OK, 2 rows affected (0.02 sec)

Records: 2 Duplicates: 0 Warnings: 0

mysql> show global status like 'InnoDB_R%';

+-------------------------------+-------+

| Variable_name | Value |

+-------------------------------+-------+

| Innodb_row_lock_current_waits | 0 |

| Innodb_row_lock_time | 0 |

| Innodb_row_lock_time_avg | 0 |

| Innodb_row_lock_time_max | 0 |

| Innodb_row_lock_waits | 0 |

| Innodb_rows_deleted | 16 |

| Innodb_rows_inserted | 39 |

| Innodb_rows_read | 4679 |

| Innodb_rows_updated | 341 |

+-------------------------------+-------+

9 rows in set (0.00 sec)

mysql> exit

Bye

$ ./mysqlbinlog /var/lib/mysql/binlog.000003 -vv
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#191015 11:29:14 server id 1  end_log_pos 124 CRC32 0xd1fc759e  Start: binlog v 4, server v 8.0.18 created 191015 11:29:14
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
iq2lXQ8BAAAAeAAAAHwAAAABAAQAOC4wLjE4AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEwANAAgAAAAABAAEAAAAYAAEGggAAAAICAgCAAAACgoKKioAEjQA
CgGedfzR
'/*!*/;
# at 124
#191015 11:29:14 server id 1  end_log_pos 155 CRC32 0x09c52830  Previous-GTIDs
# [empty]
# at 155
#191015 11:30:19 server id 1  end_log_pos 234 CRC32 0x0b72fbd9  Anonymous_GTID  last_committed=0        sequence_number=1                                                                           rbr_only=yes     original_committed_timestamp=1571139019517356   immediate_commit_timestamp=1571139019517356                                                                                         transaction_length=357
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1571139019517356 (2019-10-15 11:30:19.517356 UTC)
# immediate_commit_timestamp=1571139019517356 (2019-10-15 11:30:19.517356 UTC)
/*!80001 SET @@session.original_commit_timestamp=1571139019517356*//*!*/;
/*!80014 SET @@session.original_server_version=80018*//*!*/;
/*!80014 SET @@session.immediate_server_version=80018*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 234
#191015 11:30:19 server id 1  end_log_pos 309 CRC32 0x49e79d20  Query   thread_id=144   exec_time=0     error_code=0
SET TIMESTAMP=1571139019/*!*/;
SET @@session.pseudo_thread_id=144/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 309
#191015 11:30:19 server id 1  end_log_pos 375 CRC32 0x282997b8  Rows_query
# insert into sejima (`rank`) values (3),(4)
# at 375
#191015 11:30:19 server id 1  end_log_pos 428 CRC32 0x7d597706  Table_map: `test`.`sejima` mapped to number 91
# at 428
#191015 11:30:19 server id 1  end_log_pos 481 CRC32 0xd440841e  Write_rows: table id 91 flags: STMT_END_F

BINLOG '
y62lXR0BAAAAQgAAAHcBAACAACppbnNlcnQgaW50byBzZWppbWEgKGByYW5rYCkgdmFsdWVzICgz
KSwoNCm4lyko
y62lXRMBAAAANQAAAKwBAAAAAFsAAAAAAAEABHRlc3QABnNlamltYQACAwMAAAEBAAZ3WX0=
y62lXR4BAAAANQAAAOEBAAAAAFsAAAAAAAEAAgAC/wBR/w4AAwAAAABS/w4ABAAAAB6EQNQ=
'/*!*/;
### INSERT INTO `test`.`sejima`
### SET
###   @1=982865 /* INT meta=0 nullable=0 is_null=0 */
###   @2=3 /* INT meta=0 nullable=0 is_null=0 */
### INSERT INTO `test`.`sejima`
### SET
###   @1=982866 /* INT meta=0 nullable=0 is_null=0 */
###   @2=4 /* INT meta=0 nullable=0 is_null=0 */
# at 481
#191015 11:30:19 server id 1  end_log_pos 512 CRC32 0x732827f3  Xid = 305
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
$

$ ./mysqlbinlog /var/lib/mysql/binlog.000003 -vv

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;

/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;

DELIMITER /*!*/;

# at 4

#191015 11:29:14 server id 1 end_log_pos 124 CRC32 0xd1fc759e Start: binlog v 4, server v 8.0.18 created 191015 11:29:14

# Warning: this binlog is either in use or was not closed properly.

BINLOG '

iq2lXQ8BAAAAeAAAAHwAAAABAAQAOC4wLjE4AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA

AAAAAAAAAAAAAAAAAAAAAAAAEwANAAgAAAAABAAEAAAAYAAEGggAAAAICAgCAAAACgoKKioAEjQA

CgGedfzR

'/*!*/;

# at 124

#191015 11:29:14 server id 1 end_log_pos 155 CRC32 0x09c52830 Previous-GTIDs

# [empty]

# at 155

#191015 11:30:19 server id 1 end_log_pos 234 CRC32 0x0b72fbd9 Anonymous_GTID last_committed=0 sequence_number=1 rbr_only=yes original_committed_timestamp=1571139019517356 immediate_commit_timestamp=1571139019517356 transaction_length=357

/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;

# original_commit_timestamp=1571139019517356 (2019-10-15 11:30:19.517356 UTC)

# immediate_commit_timestamp=1571139019517356 (2019-10-15 11:30:19.517356 UTC)

/*!80001 SET @@session.original_commit_timestamp=1571139019517356*//*!*/;

/*!80014 SET @@session.original_server_version=80018*//*!*/;

/*!80014 SET @@session.immediate_server_version=80018*//*!*/;

SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;

# at 234

#191015 11:30:19 server id 1 end_log_pos 309 CRC32 0x49e79d20 Query thread_id=144 exec_time=0 error_code=0

SET TIMESTAMP=1571139019/*!*/;

SET @@session.pseudo_thread_id=144/*!*/;

SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;

SET @@session.sql_mode=1168113696/*!*/;

SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;

/*!\C latin1 *//*!*/;

SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=255/*!*/;

SET @@session.lc_time_names=0/*!*/;

SET @@session.collation_database=DEFAULT/*!*/;

/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;

BEGIN

/*!*/;

# at 309

#191015 11:30:19 server id 1 end_log_pos 375 CRC32 0x282997b8 Rows_query

# insert into sejima (`rank`) values (3),(4)

# at 375

#191015 11:30:19 server id 1 end_log_pos 428 CRC32 0x7d597706 Table_map: `test`.`sejima` mapped to number 91

# at 428

#191015 11:30:19 server id 1 end_log_pos 481 CRC32 0xd440841e Write_rows: table id 91 flags: STMT_END_F

BINLOG '

y62lXR0BAAAAQgAAAHcBAACAACppbnNlcnQgaW50byBzZWppbWEgKGByYW5rYCkgdmFsdWVzICgz

KSwoNCm4lyko

y62lXRMBAAAANQAAAKwBAAAAAFsAAAAAAAEABHRlc3QABnNlamltYQACAwMAAAEBAAZ3WX0=

y62lXR4BAAAANQAAAOEBAAAAAFsAAAAAAAEAAgAC/wBR/w4AAwAAAABS/w4ABAAAAB6EQNQ=

'/*!*/;

### INSERT INTO `test`.`sejima`

### SET

### @1=982865 /* INT meta=0 nullable=0 is_null=0 */

### @2=3 /* INT meta=0 nullable=0 is_null=0 */

### INSERT INTO `test`.`sejima`

### SET

### @1=982866 /* INT meta=0 nullable=0 is_null=0 */

### @2=4 /* INT meta=0 nullable=0 is_null=0 */

# at 481

#191015 11:30:19 server id 1 end_log_pos 512 CRC32 0x732827f3 Xid = 305

COMMIT/*!*/;

SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;

DELIMITER ;

# End of log file

/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

handler 経由で InnoDB を更新してて、 handler API 経由で record 追加したときに WRITE_ROWS_EVENT を transaction cache に書いているわけなので

WRITE_ROWS_EVENT で行が追加されているということは、それだけ Innodb_rows_inserted も増えています。
余談ですが、WRITE_ROWS_EVENT で record 一件あたりどれくらいのデータが追加されそうかは、 Avg_row_length を参考にできる可能性があります。（Avg_row_length はちょうざっくりした概算なので、あくまで参考にしかならないですが）。

ちなみに、binlog_rows_query_log_events を有効にすると、 binlog_format=ROW のときでも statement を binary log にコメントとして記録することができます。具体的には、上記の例だと Rows_query がそれに当たります。

例えば、 show binlog events で見ると次のようになります。 Query は binlog_format=STATEMENT で実行した query で、 Rows_query や Writes_rows が、 binlog_format=ROW で実行した結果です。

mysql> select @@version;
+-----------+
| @@version |
+-----------+
| 8.0.18    |
+-----------+
1 row in set (0.00 sec)

mysql> show binlog events in 'binlog.000003';
+---------------+-----+----------------+-----------+-------------+----------------------------------------------+
| Log_name      | Pos | Event_type     | Server_id | End_log_pos | Info                                         |
+---------------+-----+----------------+-----------+-------------+----------------------------------------------+
| binlog.000003 |   4 | Format_desc    |         1 |         124 | Server ver: 8.0.18, Binlog ver: 4            |
| binlog.000003 | 124 | Previous_gtids |         1 |         155 |                                              |
| binlog.000003 | 155 | Anonymous_Gtid |         1 |         234 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'         |
| binlog.000003 | 234 | Query          |         1 |         309 | BEGIN                                        |
| binlog.000003 | 309 | Rows_query     |         1 |         375 | # insert into sejima (`rank`) values (3),(4) |
| binlog.000003 | 375 | Table_map      |         1 |         428 | table_id: 91 (test.sejima)                   |
| binlog.000003 | 428 | Write_rows     |         1 |         481 | table_id: 91 flags: STMT_END_F               |
| binlog.000003 | 481 | Xid            |         1 |         512 | COMMIT /* xid=305 */                         |
+---------------+-----+----------------+-----------+-------------+----------------------------------------------+
8 rows in set (0.00 sec)

mysql>

mysql> select @@version;

+-----------+

| @@version |

+-----------+

| 8.0.18 |

+-----------+

1 row in set (0.00 sec)

mysql> show binlog events in 'binlog.000003';

+---------------+-----+----------------+-----------+-------------+----------------------------------------------+

+---------------+-----+----------------+-----------+-------------+----------------------------------------------+

| binlog.000003 | 4 | Format_desc | 1 | 124 | Server ver: 8.0.18, Binlog ver: 4 |

| binlog.000003 | 124 | Previous_gtids | 1 | 155 | |

| binlog.000003 | 155 | Anonymous_Gtid | 1 | 234 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |

| binlog.000003 | 234 | Query | 1 | 309 | BEGIN |

| binlog.000003 | 309 | Rows_query | 1 | 375 | # insert into sejima (`rank`) values (3),(4) |

| binlog.000003 | 375 | Table_map | 1 | 428 | table_id: 91 (test.sejima) |

| binlog.000003 | 428 | Write_rows | 1 | 481 | table_id: 91 flags: STMT_END_F |

| binlog.000003 | 481 | Xid | 1 | 512 | COMMIT /* xid=305 */ |

+---------------+-----+----------------+-----------+-------------+----------------------------------------------+

8 rows in set (0.00 sec)

mysql>

Rows_query がいつ transaction cache に書かれるかというと、もういちど、handler::ha_update_row() あたりから読むとわかりやすいです。

https://github.com/mysql/mysql-server/blob//mysql-8.0.12/sql/handler.cc#L7490

https://github.com/mysql/mysql-server/blob//mysql-8.0.12/sql/handler.cc#L7513

https://github.com/mysql/mysql-server/blob//mysql-8.0.12/sql/handler.cc#L7350

https://github.com/mysql/mysql-server/blob//mysql-8.0.12/sql/handler.cc#L7298

https://github.com/mysql/mysql-server/blob//mysql-8.0.12/sql/handler.cc#L7311

binlog_rows_query_log_events が true な場合、

      bool need_binlog_rows_query = thd->variables.binlog_rows_query_log_events;

7311	bool need_binlog_rows_query = thd->variables.binlog_rows_query_log_events;

https://github.com/mysql/mysql-server/blob//mysql-8.0.12/sql/handler.cc#L7333

          int const error = thd->binlog_write_table_map(table, has_trans,
                                                        need_binlog_rows_query);

7333

7334

int const error = thd->binlog_write_table_map(table, has_trans,

need_binlog_rows_query);

https://github.com/mysql/mysql-server/blob//mysql-8.0.12/sql/binlog.cc#L9376

https://github.com/mysql/mysql-server/blob//mysql-8.0.12/sql/binlog.cc#L9397

  if (binlog_rows_query && this->query().str) {
    /* Write the Rows_query_log_event into binlog before the table map */
    Rows_query_log_event rows_query_ev(this, this->query().str,
                                       this->query().length);
    if ((error = cache_data->write_event(this, &rows_query_ev)))
      DBUG_RETURN(error);
  }

  if ((error = cache_data->write_event(this, &the_event))) DBUG_RETURN(error);

9397

9398

9399

9400

9401

9402

9403

9404

9405

if (binlog_rows_query && this->query().str) {

/* Write the Rows_query_log_event into binlog before the table map */

Rows_query_log_event rows_query_ev(this, this->query().str,

this->query().length);

if ((error = cache_data->write_event(this, &rows_query_ev)))

DBUG_RETURN(error);

}

if ((error = cache_data->write_event(this, &the_event))) DBUG_RETURN(error);

上記の show binlog events; のように、 Table_map(TABLE_MAP_EVENT) を書く前にRows_query(ROWS_QUERY_LOG_EVENT) を書いています。

TABLE_MAP_EVENT については、このあたりが詳しいです。

Used for row-based binary logging. This event precedes each row operation event. It maps a table definition to a number, where the table definition consists of database and table names and column definitions. The purpose of this event is to enable replication when a table has different definitions on the master and slave. Row operation events that belong to the same transaction may be grouped into sequences, in which case each such sequence of events begins with a sequence ofTABLE_MAP_EVENT events: one per table used by events in the sequence.

20.9 Event Data for Specific Event Types

雑に考えると、 InnoDB は内部的に *.ibd ごとに table の id を割り当てているのですが、 table の作成順序や table の個数が master と slave で完全に一致するとは限りません。なので、 master と slave で（内部的な） table の id が一致するとも限らないので、 database の名前と table 名、そしてその table に対する一意な id を TABLE_MAP_EVENT で割り当てることにより、 TABLE_MAP_EVENT の後に続く WRITE_ROWS_EVENT で対象のテーブルを更新できる、ということではないでしょうか。

例えば上記の show binlog events でいうと、 Anonymous_Gtid から Xid（COMMIT）
までが一連のトランザクションとなるのではないかと。

| binlog.000003 | 155 | Anonymous_Gtid |         1 |         234 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'         |
| binlog.000003 | 234 | Query          |         1 |         309 | BEGIN                                        |
| binlog.000003 | 309 | Rows_query     |         1 |         375 | # insert into sejima (`rank`) values (3),(4) |
| binlog.000003 | 375 | Table_map      |         1 |         428 | table_id: 91 (test.sejima)                   |
| binlog.000003 | 428 | Write_rows     |         1 |         481 | table_id: 91 flags: STMT_END_F               |
| binlog.000003 | 481 | Xid            |         1 |         512 | COMMIT /* xid=305 */                         |

| binlog.000003 | 155 | Anonymous_Gtid | 1 | 234 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |

| binlog.000003 | 234 | Query | 1 | 309 | BEGIN |

| binlog.000003 | 309 | Rows_query | 1 | 375 | # insert into sejima (`rank`) values (3),(4) |

| binlog.000003 | 375 | Table_map | 1 | 428 | table_id: 91 (test.sejima) |

| binlog.000003 | 428 | Write_rows | 1 | 481 | table_id: 91 flags: STMT_END_F |

| binlog.000003 | 481 | Xid | 1 | 512 | COMMIT /* xid=305 */ |

ROWS_QUERY_LOG_EVENT に関する WorkLog など

Bug #50935 Record original SQL statement in RBR binlog という Feature request が事の発端であるようです

To aid in debugging replication issues, it would help to have the full
original SQL statement (including any embedded comments) recorded in the
binlog when in RBR mode.
The reconstructed pseudo-SQL is not always sufficient to uniquely
identify the source of the statement.

binary log 使って Point In Time Recovery したり duplicate した event を skip したりすると
き、元の query が log にないと困るだろう、ということでしょう。

そして MySQL5.6 で binlog_rows_query_log_events が追加され、

WL#4033: Support for informational log events

mysqlbinlog -vv で、 ROWS_QUERY_LOG_EVENT はコメントとして表示されるようになった模様です。

WL#5404: Propagation of Rows_query log event

今日はこれまで

もともとが社内文書なので、こういったノリで淡々と続きます。一年ぶりに読み返して見ると、我ながら随分そっけないなと思いました。

次回以降も、 RBR の話は続きます。

はじめに

解説

前提： そもそも binary log による replication とは

binlog_format=ROW になったとき、binlog event はどの時点で transaction cache に書き出されるのか

ちなみに、 binlog_format=statement の場合は

具体的に確認すると

ROWS_QUERY_LOG_EVENT に関する WorkLog など

今日はこれまで

前提：そもそも binary log による replication とは