← Back to team overview

maria-developers team mailing list archive

MWL#47 documentation

 

Hi Daniel,

I merged the MWL#47 patch into 5.2-percona, which will later be included in
5.3.

I have attached the documentation for this worklog that Alexi wrote (he also
implemented the feature itself). I hope you can adapt it as needed and find a
good place for it in the server documentation.

 - Kristian.

WL#47: Store in binlog text of statements that caused RBR events
================================================================

Content
~~~~~~~
1. Annotate_rows_log_event [ ANNOTATE_ROWS_EVENT ]
2. Example
3. Master option: --binlog-annotate-rows-events
4. Slave option: --replicate-annotate-rows-events
5. mysqlbinlog option: --skip-annotate-rows-events
6. Example of mysqlbinlog output


1. Annotate_rows_log_event [ ANNOTATE_ROWS_EVENT ]
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
New binlog event type - Annotate_rows_log_event - is added. The events of
this type accompany rows events and describe the query which caused these
rows events.

In binary log, each Annotate_rows event precedes the corresponding Table
map event or the first of Table map events, if there are more than one
(e.g. in case of multi-delete or insert delayed).

2. Example
~~~~~~~~~~

master> DROP DATABASE IF EXISTS test;
master> CREATE DATABASE test;
master> USE test;
master> CREATE TABLE t1(a int);
master> INSERT INTO t1 VALUES (1), (2), (3);
master> CREATE TABLE t2(a int);
master> INSERT INTO t2 VALUES (1), (2), (3);
master> CREATE TABLE t3(a int);
master> INSERT DELAYED INTO t3 VALUES (1), (2), (3);
master> DELETE t1, t2 FROM t1 INNER JOIN t2 INNER JOIN t3
    ->        WHERE t1.a=t2.a AND t2.a=t3.a;
    
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   |       100 |         240 | Server ver: 5.1.44-debug-log, Binlog ver: 4       |
| master-bin.000001 |  240 | Query         |       100 |         331 | DROP DATABASE IF EXISTS test                      |
| master-bin.000001 |  331 | Query         |       100 |         414 | CREATE DATABASE test                              |
| master-bin.000001 |  414 | Query         |       100 |         499 | use `test`; CREATE TABLE t1(a int)                |
| master-bin.000001 |  499 | Query         |       100 |         567 | BEGIN                                             |
| master-bin.000001 |  567 | Annotate_rows |       100 |         621 | INSERT INTO t1 VALUES (1), (2), (3)               |
| master-bin.000001 |  621 | Table_map     |       100 |         662 | table_id: 16 (test.t1)                            |
| master-bin.000001 |  662 | Write_rows    |       100 |         706 | table_id: 16 flags: STMT_END_F                    |
| master-bin.000001 |  706 | Query         |       100 |         775 | COMMIT                                            |
| master-bin.000001 |  775 | Query         |       100 |         860 | use `test`; CREATE TABLE t2(a int)                |
| master-bin.000001 |  860 | Query         |       100 |         928 | BEGIN                                             |
| master-bin.000001 |  928 | Annotate_rows |       100 |         982 | INSERT INTO t2 VALUES (1), (2), (3)               |
| master-bin.000001 |  982 | Table_map     |       100 |        1023 | table_id: 17 (test.t2)                            |
| master-bin.000001 | 1023 | Write_rows    |       100 |        1067 | table_id: 17 flags: STMT_END_F                    |
| master-bin.000001 | 1067 | Query         |       100 |        1136 | COMMIT                                            |
| master-bin.000001 | 1136 | Query         |       100 |        1221 | use `test`; CREATE TABLE t3(a int)                |
| master-bin.000001 | 1221 | Query         |       100 |        1289 | BEGIN                                             |
| master-bin.000001 | 1289 | Annotate_rows |       100 |        1351 | INSERT DELAYED INTO t3 VALUES (1), (2), (3)       |
| master-bin.000001 | 1351 | Table_map     |       100 |        1392 | table_id: 18 (test.t3)                            |
| master-bin.000001 | 1392 | Write_rows    |       100 |        1426 | table_id: 18 flags: STMT_END_F                    |
| master-bin.000001 | 1426 | Table_map     |       100 |        1467 | table_id: 18 (test.t3)                            |
| master-bin.000001 | 1467 | Write_rows    |       100 |        1506 | table_id: 18 flags: STMT_END_F                    |
| master-bin.000001 | 1506 | Query         |       100 |        1575 | COMMIT                                            |
| master-bin.000001 | 1575 | Query         |       100 |        1643 | BEGIN                                             |
| master-bin.000001 | 1643 | Annotate_rows |       100 |        1748 | DELETE t1, t2 FROM t1 INNER JOIN t2 INNER JOIN t3 
       WHERE t1.a=t2.a AND t2.a=t3.a                                                                                     |
| master-bin.000001 | 1748 | Table_map     |       100 |        1789 | table_id: 16 (test.t1)                            |
| master-bin.000001 | 1789 | Table_map     |       100 |        1830 | table_id: 17 (test.t2)                            |
| master-bin.000001 | 1830 | Delete_rows   |       100 |        1874 | table_id: 16                                      |
| master-bin.000001 | 1874 | Delete_rows   |       100 |        1918 | table_id: 17 flags: STMT_END_F                    |
| master-bin.000001 | 1918 | Query         |       100 |        1987 | COMMIT                                            |
+-------------------+------+---------------+-----------+-------------+---------------------------------------------------+

3. Master option: --binlog-annotate-rows-events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Tells the master to write Annotate_rows events to the binary log.

    * Variable Name: binlog_annotate_rows_events
    * Scope: Global & Session
    * Access Type: Dynamic
    * Data Type: bool
    * Default Value: OFF

Session values allows to annotate only some selected statements:
    ...
    SET SESSION binlog_annotate_rows_events=ON;
    ... statements to be annotated ...
    SET SESSION binlog_annotate_rows_events=OFF;
    ... statements not to be annotated ...

4. Slave option: --replicate-annotate-rows-events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Tells the slave to reproduce Annotate_rows events recieved from the master
in its own binary log (sensible only in pair with log-slave-updates option).

    * Variable Name: replicate_annotate_rows_events
    * Scope: Global
    * Access Type: Read only (only in config file)
    * Data Type: bool
    * Default Value: OFF

5. mysqlbinlog option: --skip-annotate-rows-events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Tells mysqlbinlog to skip all Annotate_rows events in its output
(by default, mysqlbinlog prints Annotate_rows events, if the binary
log does contain them). 

6. Example of mysqlbinlog output
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

...> mysqlbinlog.exe -vv -R --user=root --port=3306 --host=localhost master-bin.000001

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#100516 15:36:00 server id 100  end_log_pos 240         Start: binlog v 4, server v 5.1.44-debug-log created 100516
 15:36:00 at startup
ROLLBACK/*!*/;
BINLOG '
oNjvSw9kAAAA7AAAAPAAAAAAAAQANS4xLjQ0LWRlYnVnLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAACg2O9LEzgNAAgAEgAEBAQEEgAA2QAEGggAAAAICAgCAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAA=
'/*!*/;
# at 240
#100516 15:36:18 server id 100  end_log_pos 331         Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1
/*!*/;
SET @@session.sql_mode=0/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
DROP DATABASE IF EXISTS test
/*!*/;
# at 331
#100516 15:36:18 server id 100  end_log_pos 414         Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
CREATE DATABASE test
/*!*/;
# at 414
#100516 15:36:18 server id 100  end_log_pos 499         Query   thread_id=1     exec_time=0     error_code=0
use test/*!*/;
SET TIMESTAMP=1274009778/*!*/;
CREATE TABLE t1(a int)
/*!*/;
# at 499
#100516 15:36:18 server id 100  end_log_pos 567         Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
BEGIN
/*!*/;
# at 567
# at 621
# at 662
#100516 15:36:18 server id 100  end_log_pos 621         Annotate_rows:
#Q> INSERT INTO t1 VALUES (1), (2), (3)
#100516 15:36:18 server id 100  end_log_pos 662         Table_map: `test`.`t1` mapped to number 16
#100516 15:36:18 server id 100  end_log_pos 706         Write_rows: table id 16 flags: STMT_END_F

BINLOG '
stjvSxNkAAAAKQAAAJYCAAAAABAAAAAAAAAABHRlc3QAAnQxAAEDAAE=
stjvSxdkAAAALAAAAMICAAAQABAAAAAAAAEAAf/+AQAAAP4CAAAA/gMAAAA=
'/*!*/;
### INSERT INTO test.t1
### SET
###   @1=1 /* INT meta=0 nullable=1 is_null=0 */
### INSERT INTO test.t1
### SET
###   @1=2 /* INT meta=0 nullable=1 is_null=0 */
### INSERT INTO test.t1
### SET
###   @1=3 /* INT meta=0 nullable=1 is_null=0 */
# at 706
#100516 15:36:18 server id 100  end_log_pos 775         Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
COMMIT
/*!*/;
# at 775
#100516 15:36:18 server id 100  end_log_pos 860         Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
CREATE TABLE t2(a int)
/*!*/;
# at 860
#100516 15:36:18 server id 100  end_log_pos 928         Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
BEGIN
/*!*/;
# at 928
# at 982
# at 1023
#100516 15:36:18 server id 100  end_log_pos 982         Annotate_rows:
#Q> INSERT INTO t2 VALUES (1), (2), (3)
#100516 15:36:18 server id 100  end_log_pos 1023        Table_map: `test`.`t2` mapped to number 17
#100516 15:36:18 server id 100  end_log_pos 1067        Write_rows: table id 17 flags: STMT_END_F

BINLOG '
stjvSxNkAAAAKQAAAP8DAAAAABEAAAAAAAAABHRlc3QAAnQyAAEDAAE=
stjvSxdkAAAALAAAACsEAAAQABEAAAAAAAEAAf/+AQAAAP4CAAAA/gMAAAA=
'/*!*/;
### INSERT INTO test.t2
### SET
###   @1=1 /* INT meta=0 nullable=1 is_null=0 */
### INSERT INTO test.t2
### SET
###   @1=2 /* INT meta=0 nullable=1 is_null=0 */
### INSERT INTO test.t2
### SET
###   @1=3 /* INT meta=0 nullable=1 is_null=0 */
# at 1067
#100516 15:36:18 server id 100  end_log_pos 1136        Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
COMMIT
/*!*/;
# at 1136
#100516 15:36:18 server id 100  end_log_pos 1221        Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
CREATE TABLE t3(a int)
/*!*/;
# at 1221
#100516 15:36:18 server id 100  end_log_pos 1289        Query   thread_id=2     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
BEGIN
/*!*/;
# at 1289
# at 1351
# at 1392
#100516 15:36:18 server id 100  end_log_pos 1351        Annotate_rows:
#Q> INSERT DELAYED INTO t3 VALUES (1), (2), (3)
#100516 15:36:18 server id 100  end_log_pos 1392        Table_map: `test`.`t3` mapped to number 18
#100516 15:36:18 server id 100  end_log_pos 1426        Write_rows: table id 18 flags: STMT_END_F

BINLOG '
stjvSxNkAAAAKQAAAHAFAAAAABIAAAAAAAAABHRlc3QAAnQzAAEDAAE=
stjvSxdkAAAAIgAAAJIFAAAQABIAAAAAAAEAAf/+AQAAAA==
'/*!*/;
### INSERT INTO test.t3
### SET
###   @1=1 /* INT meta=0 nullable=1 is_null=0 */
# at 1426
# at 1467
#100516 15:36:18 server id 100  end_log_pos 1467        Table_map: `test`.`t3` mapped to number 18
#100516 15:36:18 server id 100  end_log_pos 1506        Write_rows: table id 18 flags: STMT_END_F

BINLOG '
stjvSxNkAAAAKQAAALsFAAAAABIAAAAAAAAABHRlc3QAAnQzAAEDAAE=
stjvSxdkAAAAJwAAAOIFAAAQABIAAAAAAAEAAf/+AgAAAP4DAAAA
'/*!*/;
### INSERT INTO test.t3
### SET
###   @1=2 /* INT meta=0 nullable=1 is_null=0 */
### INSERT INTO test.t3
### SET
###   @1=3 /* INT meta=0 nullable=1 is_null=0 */
# at 1506
#100516 15:36:18 server id 100  end_log_pos 1575        Query   thread_id=2     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
COMMIT
/*!*/;
# at 1575
#100516 15:36:18 server id 100  end_log_pos 1643        Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
BEGIN
/*!*/;
# at 1643
# at 1748
# at 1789
# at 1830
# at 1874
#100516 15:36:18 server id 100  end_log_pos 1748        Annotate_rows:
#Q> DELETE t1, t2 FROM t1 INNER JOIN t2 INNER JOIN t3
#Q>        WHERE t1.a=t2.a AND t2.a=t3.
#100516 15:36:18 server id 100  end_log_pos 1789        Table_map: `test`.`t1` mapped to number 16
#100516 15:36:18 server id 100  end_log_pos 1830        Table_map: `test`.`t2` mapped to number 17
#100516 15:36:18 server id 100  end_log_pos 1874        Delete_rows: table id 16
#100516 15:36:18 server id 100  end_log_pos 1918        Delete_rows: table id 17 flags: STMT_END_F

BINLOG '
stjvSxNkAAAAKQAAAP0GAAAAABAAAAAAAAAABHRlc3QAAnQxAAEDAAE=
stjvSxNkAAAAKQAAACYHAAAAABEAAAAAAAAABHRlc3QAAnQyAAEDAAE=
stjvSxlkAAAALAAAAFIHAAAAABAAAAAAAAAAAf/+AQAAAP4CAAAA/gMAAAA=
### DELETE FROM test.t1
### WHERE
###   @1=1 /* INT meta=0 nullable=1 is_null=0 */
### DELETE FROM test.t1
### WHERE
###   @1=2 /* INT meta=0 nullable=1 is_null=0 */
### DELETE FROM test.t1
### WHERE
###   @1=3 /* INT meta=0 nullable=1 is_null=0 */
stjvSxlkAAAALAAAAH4HAAAQABEAAAAAAAEAAf/+AQAAAP4CAAAA/gMAAAA=
'/*!*/;
### DELETE FROM test.t2
### WHERE
###   @1=1 /* INT meta=0 nullable=1 is_null=0 */
### DELETE FROM test.t2
### WHERE
###   @1=2 /* INT meta=0 nullable=1 is_null=0 */
### DELETE FROM test.t2
### WHERE
###   @1=3 /* INT meta=0 nullable=1 is_null=0 */
# at 1918
#100516 15:36:18 server id 100  end_log_pos 1987        Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1274009778/*!*/;
COMMIT
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;