Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-16370

row-based binlog events (updates by primary key) can not be applied multiple times to system versioned tables

    XMLWordPrintable

    Details

      Description

      Normally one can re-apply row-based events from the binary log (at least single row updates of non-key column by the primary key) as many times as needed. Consider this simple scenario:

      openxs@ao756:~/dbs/maria10.3$ bin/mysql --socket=/tmp/mariadb.sock -uroot test  Reading table information for completion of table and column names
      You can turn off this feature to get a quicker startup with -A
       
      Welcome to the MariaDB monitor.  Commands end with ; or \g.
      Your MariaDB connection id is 9
      Server version: 10.3.8-MariaDB-log Source distribution
       
      Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
       
      Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
       
      MariaDB [test]> create table tv(id int primary key, val int);
      Query OK, 0 rows affected (0.400 sec)
       
      MariaDB [test]> insert into tv values (1, 1);
      Query OK, 1 row affected (0.049 sec)
       
      MariaDB [test]> reset master;
      Query OK, 0 rows affected (0.166 sec)
       
      MariaDB [test]> show master status;
      +------------------+----------+--------------+------------------+
      | File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
      +------------------+----------+--------------+------------------+
      | ao756-bin.000001 |      328 |              |                  |
      +------------------+----------+--------------+------------------+
      1 row in set (0.000 sec)
       
      MariaDB [test]> select @@binlog_format, @@binlog_row_image;
      +-----------------+--------------------+
      | @@binlog_format | @@binlog_row_image |
      +-----------------+--------------------+
      | ROW             | FULL               |
      +-----------------+--------------------+
      1 row in set (0.000 sec)
       
      MariaDB [test]> update tv set val = 2 where id = 1;
      Query OK, 1 row affected (0.067 sec)
      Rows matched: 1  Changed: 1  Warnings: 0
       
      MariaDB [test]> update tv set val = 3 where id = 1;
      Query OK, 1 row affected (0.037 sec)
      Rows matched: 1  Changed: 1  Warnings: 0
       
      MariaDB [test]> select * from tv;
      +----+------+
      | id | val  |
      +----+------+
      |  1 |    3 |
      +----+------+
      1 row in set (0.001 sec)
       
      MariaDB [test]> flush logs;
      Query OK, 0 rows affected (0.170 sec)
       
      MariaDB [test]> exit
      Bye
      

      As a result we get a binary log with two row-based updates:

      openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001
      /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
      /*!40019 SET @@session.max_insert_delayed_threads=0*/;
      /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
      DELIMITER /*!*/;
      # at 4
      #180601 15:25:54 server id 1  end_log_pos 256 CRC32 0xbde756f2  Start: binlog v 4, server v 10.3.8-MariaDB-log created 180601 15:25:54 at startup
      ROLLBACK/*!*/;
      BINLOG '
      UjsRWw8BAAAA/AAAAAABAAAAAAQAMTAuMy44LU1hcmlhREItbG9nAAAAAAAAAAAAAAAAAAAAAAAA
      AAAAAAAAAAAAAAAAAABSOxFbEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA
      AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
      AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
      AAAAAAAAAAAEEwQADQgICAoKCgHyVue9
      '/*!*/;
      # at 256
      #180601 15:25:54 server id 1  end_log_pos 285 CRC32 0xefe84001  Gtid list []
      # at 285
      #180601 15:25:54 server id 1  end_log_pos 328 CRC32 0x77ed5780  Binlog checkpoint ao756-bin.000001
      # at 328
      #180601 15:26:31 server id 1  end_log_pos 370 CRC32 0x85964c7e  GTID 0-1-1 trans
      /*!100101 SET @@session.skip_parallel_replication=0*//*!*/;
      /*!100001 SET @@session.gtid_domain_id=0*//*!*/;
      /*!100001 SET @@session.server_id=1*//*!*/;
      /*!100001 SET @@session.gtid_seq_no=1*//*!*/;
      BEGIN
      /*!*/;
      # at 370
      # at 427
      #180601 15:26:31 server id 1  end_log_pos 427 CRC32 0x3404421b  Annotate_rows:
      #Q> update tv set val = 2 where id = 1
      #180601 15:26:31 server id 1  end_log_pos 473 CRC32 0xe650f843  Table_map: `test`.`tv` mapped to number 20
      # at 473
      #180601 15:26:31 server id 1  end_log_pos 525 CRC32 0x3d3cbe3c  Update_rows: table id 20 flags: STMT_END_F
       
      BINLOG '
      dzsRWxMBAAAALgAAANkBAAAAABQAAAAAAAEABHRlc3QAAnR2AAIDAwACQ/hQ5g==
      dzsRWxgBAAAANAAAAA0CAAAAABQAAAAAAAEAAv///AEAAAABAAAA/AEAAAACAAAAPL48PQ==
      '/*!*/;
      ### UPDATE `test`.`tv`
      ### WHERE
      ###   @1=1
      ###   @2=1
      ### SET
      ###   @1=1
      ###   @2=2
      # Number of rows: 1
      # at 525
      #180601 15:26:31 server id 1  end_log_pos 556 CRC32 0x30719438  Xid = 11
      COMMIT/*!*/;
      # at 556
      #180601 15:26:36 server id 1  end_log_pos 598 CRC32 0xcfc49d29  GTID 0-1-2 trans
      /*!100001 SET @@session.gtid_seq_no=2*//*!*/;
      BEGIN
      /*!*/;
      # at 598
      # at 655
      #180601 15:26:36 server id 1  end_log_pos 655 CRC32 0x5be0a3bd  Annotate_rows:
      #Q> update tv set val = 3 where id = 1
      #180601 15:26:36 server id 1  end_log_pos 701 CRC32 0x221100ed  Table_map: `test`.`tv` mapped to number 20
      # at 701
      #180601 15:26:36 server id 1  end_log_pos 753 CRC32 0x2c6ee1de  Update_rows: table id 20 flags: STMT_END_F
       
      BINLOG '
      fDsRWxMBAAAALgAAAL0CAAAAABQAAAAAAAEABHRlc3QAAnR2AAIDAwAC7QARIg==
      fDsRWxgBAAAANAAAAPECAAAAABQAAAAAAAEAAv///AEAAAACAAAA/AEAAAADAAAA3uFuLA==
      '/*!*/;
      ### UPDATE `test`.`tv`
      ### WHERE
      ###   @1=1
      ###   @2=2
      ### SET
      ###   @1=1
      ###   @2=3
      # Number of rows: 1
      # at 753
      #180601 15:26:36 server id 1  end_log_pos 784 CRC32 0x17176a74  Xid = 12
      COMMIT/*!*/;
      # at 784
      #180601 15:26:46 server id 1  end_log_pos 831 CRC32 0x9b00b198  Rotate to ao756-bin.000002  pos: 4
      DELIMITER ;
      # End of log file
      ROLLBACK /* added by mysqlbinlog */;
      /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
      /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
      

      Normally we can apply it to the table as many times as needed without errors, as long as initial state of data is consistent (row exists):

      MariaDB [test]> delete from tv;
      Query OK, 0 rows affected (0.000 sec)
       
      MariaDB [test]> insert into tv values (1, 1);
      Query OK, 1 row affected (0.031 sec)
       
      MariaDB [test]> select * from tv;
      +----+------+
      | id | val  |
      +----+------+
      |  1 |    1 |
      +----+------+
      1 row in set (0.001 sec)
       
      MariaDB [test]> exit
      Bye
      openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001 |  mysql -uroot --socket=/tmp/mariadb.sock
      openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001 |  mysql -uroot --socket=/tmp/mariadb.sock
      openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001 |  mysql -uroot --socket=/tmp/mariadb.sock
      openxs@ao756:~/dbs/maria10.3$ mysql -uroot --socket=/tmp/mariadb.sock test -e"select * from tv"
      +----+------+
      | id | val  |
      +----+------+
      |  1 |    3 |
      +----+------+
      openxs@ao756:~/dbs/maria10.3$
      

      Now, let's try to re-create the table as a system versioned one:

      MariaDB [test]> drop table tv;
      Query OK, 0 rows affected (0.215 sec)
       
      MariaDB [test]> create table tv(id int primary key, val int) with system versioning;
      Query OK, 0 rows affected (0.197 sec)
       
      MariaDB [test]> insert into tv values (1, 1);
      Query OK, 1 row affected (0.037 sec)
       
      MariaDB [test]> select *, row_start, row_end from tv;
      +----+------+----------------------------+----------------------------+
      | id | val  | row_start                  | row_end                    |
      +----+------+----------------------------+----------------------------+
      |  1 |    1 | 2018-06-01 15:40:35.061322 | 2038-01-19 05:14:07.999999 |
      +----+------+----------------------------+----------------------------+
      1 row in set (0.001 sec)
       
      MariaDB [test]> exit
      Bye
      

      We can successfully apply binary log once and get the result:

      openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001 |  mysql -uroot --socket=/tmp/mariadb.sock
      openxs@ao756:~/dbs/maria10.3$ mysql -uroot --socket=/tmp/mariadb.sock test -e"select *, row_start, row_end from tv"
      +----+------+----------------------------+----------------------------+
      | id | val  | row_start                  | row_end                    |
      +----+------+----------------------------+----------------------------+
      |  1 |    3 | 2018-06-01 15:26:36.000000 | 2038-01-19 05:14:07.999999 |
      +----+------+----------------------------+----------------------------+
      

      But if we try again we fail with error:

      openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001 |  mysql -uroot --socket=/tmp/mariadb.sock
      ERROR 1062 (23000) at line 63: Duplicate entry '1' for key 'PRIMARY'
      openxs@ao756:~/dbs/maria10.3$ mysql -uroot --socket=/tmp/mariadb.sock test -e"select *, row_start, row_end from tv"
      +----+------+----------------------------+----------------------------+
      | id | val  | row_start                  | row_end                    |
      +----+------+----------------------------+----------------------------+
      |  1 |    2 | 2018-06-01 15:26:31.000000 | 2038-01-19 05:14:07.999999 |
      +----+------+----------------------------+----------------------------+
      

      Note two things above:

      1. The error message is weird and misleading. We do have just one single row with primary key value 1, and we updated other column, not a primary key.

      2. We were able to perform the first update, but not the second. So, I'd say data are corrupted.

      Probably system versioned tables can not be treated in such a way, but then I'd appreciate proper error messages and documented limitation.

      I also strongly suspect that the same problem may happen during replication, in case of retries by SQL thread for example, or in some other, not yet identified cases. At least this my test was created while working on a problem (same error message for some of multiple single row updates) while replicating row-based changes to a more complex table from older 5.5.x MariaDB version into a similar system-versioned table on MariaDB 10.3.7 slave.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              serg Sergei Golubchik
              Reporter:
              valerii Valerii Kravchuk
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

                Dates

                Created:
                Updated: