Problem with replaying UPDATE or DELETE using key of BINARY(N) ending in 00's #654
Description
First, thanks for the development and open sourcing of this tool.
However, I was running a migration and left it postponed for a while, and before cutover I noticed that I had some differences between the master table and the gh-ost table involving columns with BINARY(N) type when values end in 00's. Perhaps I was using this incorrectly, but I distilled the problem down to these steps to reproduce. Apologies for the length.
Setup is on AWS RDS, mysql 5.6.40, gh-ost 1.0.46. RDS master is set to binlog_format of MIXED. RDS read replica is set to binlog_format of ROW.
RDS master parameter group settings difference from default:
Parameter test-rdsparamgroup default.mysql5.6
---------------------------------------------------------
general_log 1 <engine-default>
innodb_file_format Barracuda <engine-default>
innodb_flush_method O_DIRECT <system>
log_output FILE TABLE
long_query_time 0.9 <engine-default>
slow_query_log 1 <engine-default>
Steps to reproduce:
- Create a new test database with a single test table.
DROP DATABASE IF EXISTS `test_ghost`;
CREATE DATABASE `test_ghost` DEFAULT CHARACTER SET utf8mb4 COLLATE utf8mb4_bin;
USE `test_ghost`;
DROP TABLE IF EXISTS `_test_table_gho`;
DROP TABLE IF EXISTS `_test_table_ghc`;
DROP TABLE IF EXISTS `test_table`;
CREATE TABLE `test_table` (
`id` binary(16) NOT NULL,
`info` varchar(255) COLLATE utf8_unicode_ci NOT NULL,
`data` binary(8) NOT NULL,
PRIMARY KEY (`id`),
UNIQUE KEY `info` (`info`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci;
INSERT INTO `test_table` (id, info, data) VALUES
(X'11ffffffffffffffffffffffffffff00', 'item 1', X'11ffffffffffffff'), -- id ends in 00
(X'22ffffffffffffffffffffffffffff00', 'item 2', X'22ffffffffffffff'), -- id ends in 00
(X'33ffffffffffffffffffffffffffffff', 'item 3', X'33ffffffffffffff'),
(X'44ffffffffffffffffffffffffffffff', 'item 4', X'44ffffffffffffff'),
(X'55ffffffffffffffffffffffffffffff', 'item 5', X'55ffffffffffffff'),
(X'99ffffffffffffffffffffffffffffff', 'item 9', X'99ffffffffffff00'); -- data ends in 00
SELECT HEX(id) AS id, info, HEX(data) AS data FROM test_table;
mysql -NBe 'source ./bin/create-test-table.sql'
- Run a migration to add a new column to the test table and leave it postponed.
#!/usr/bin/env sh
./gh-ost \
--execute \
--max-load=Threads_running=25 \
--critical-load=Threads_running=1000 \
--assume-rbr \
--chunk-size=1000 \
--max-lag-millis=15000 \
--user='the_user' \
--password='the-password' \
--host='the-slave-hostname' \
--assume-master-host='the-master-hostname' \
--database='test_ghost' \
--table='test_table' \
--verbose \
--alter='ADD COLUMN testColumn BIGINT UNSIGNED DEFAULT NULL, ALGORITHM = INPLACE, LOCK = NONE' \
--cut-over=default \
--exact-rowcount \
--concurrent-rowcount \
--default-retries=120 \
--panic-flag-file=/tmp/ghost.panic.flag \
--postpone-cut-over-flag-file=/tmp/ghost.postpone.flag
I'll add the gh-ost output in a further comment below.
- Compare the test table to the ghost table.
#!/usr/bin/env sh
mysql test_ghost -NBe 'SELECT HEX(id) AS id, info, HEX(data) AS data FROM test_table' > /tmp/test_table.dump
mysql test_ghost -NBe 'SELECT HEX(id) AS id, info, HEX(data) AS data FROM _test_table_gho' > /tmp/_test_table_gho.dump
diff -U8 /tmp/test_table.dump /tmp/_test_table_gho.dump
md5sum /tmp/test_table.dump /tmp/_test_table_gho.dump
$ sh ./bin/compare-test-table.sh
689e658d47fd8b0e987f8356446aa05a /tmp/test_table.dump
689e658d47fd8b0e987f8356446aa05a /tmp/_test_table_gho.dump
After the initial migration, everything matches between the two tables.
- Now do an INSERT, UPDATE, and DELETE with a BINARY(16) primary key ending in
00.
-- FAIL 1. is an existing row with `id` ending in `00` mirrored correctly if deleted from master table
-- This row was not deleted from the ghost table.
DELETE FROM `test_table` WHERE id = X'11ffffffffffffffffffffffffffff00';
-- FAIL 2. is an existing row with `id` ending in `00` mirrored correctly if updated on master table
-- The ghost table was not updated
UPDATE `test_table` SET info = 'item 2++' WHERE id = X'22ffffffffffffffffffffffffffff00';
-- PASS 3. is an existing row with `id` NOT ending in `00` but `data` ending in `00` mirrored correctly if updated on master table
UPDATE `test_table` SET info = 'item 3++', data = X'33ffffffffffff00' WHERE id = X'33ffffffffffffffffffffffffffffff';
-- PASS 4. is an existing row with `id` NOT ending in `00` mirrored correctly if deleted from master table
DELETE FROM `test_table` WHERE id = X'44ffffffffffffffffffffffffffffff';
-- PASS 5. is an existing row with `id` NOT ending in `00` mirrored correctly if updated on master table
UPDATE `test_table` SET info = 'item 5++', data = X'55ffffffffffffee' WHERE id = X'55ffffffffffffffffffffffffffffff';
-- PASS 6. is a row with `id` ending in `00` mirrored correctly if inserted into master table
-- but maybe lucky with auto-padding of replace into?
INSERT INTO `test_table` (id, info, data) VALUES (X'66ffffffffffffffffffffffffffff00', 'item 6', X'66ffffffffffffff');
-- PASS 7. is a row with `id` NOT ending in `00` but `data` ending in `00` mirrored correctly if inserted into master table
INSERT INTO `test_table` (id, info, data) VALUES (X'77ffffffffffffffffffffffffffffff', 'item 7', X'77ffffffffffff00');
-- PASS 8. is a row with `id` NOT ending in `00` mirrored correctly if inserted into master table
INSERT INTO `test_table` (id, info, data) VALUES (X'88ffffffffffffffffffffffffffffff', 'item 8', X'88ffffffffffffff');
mysql test_ghost -e 'source ./bin/change-test-table.sql'
- Re-compare the test table to the ghost table. There are two differences now:
- The deletion using a BINARY(16) key has not been done on the gh-ost table.
- The update using a BINARY(16) key has not been done on the gh-ost table.
$ sh ./bin/compare-test-table.sh
--- /tmp/test_table.dump 2018-10-29 01:07:39.349169830 +0000
+++ /tmp/_test_table_gho.dump 2018-10-29 01:07:39.357169511 +0000
@@ -1,7 +1,8 @@
-22FFFFFFFFFFFFFFFFFFFFFFFFFFFF00 item 2++ 22FFFFFFFFFFFFFF
+11FFFFFFFFFFFFFFFFFFFFFFFFFFFF00 item 1 11FFFFFFFFFFFFFF
+22FFFFFFFFFFFFFFFFFFFFFFFFFFFF00 item 2 22FFFFFFFFFFFFFF
33FFFFFFFFFFFFFFFFFFFFFFFFFFFFFF item 3++ 33FFFFFFFFFFFF00
55FFFFFFFFFFFFFFFFFFFFFFFFFFFFFF item 5++ 55FFFFFFFFFFFFEE
66FFFFFFFFFFFFFFFFFFFFFFFFFFFF00 item 6 66FFFFFFFFFFFFFF
77FFFFFFFFFFFFFFFFFFFFFFFFFFFFFF item 7 77FFFFFFFFFFFF00
88FFFFFFFFFFFFFFFFFFFFFFFFFFFFFF item 8 88FFFFFFFFFFFFFF
99FFFFFFFFFFFFFFFFFFFFFFFFFFFFFF item 9 99FFFFFFFFFFFF00
8a363b2e25dceb1928df81b1ef48bba4 /tmp/test_table.dump
d65973974ef97bb8b7b95caca4bce937 /tmp/_test_table_gho.dump
- Remove the /tmp/ghost.postpone.flag file to complete the migration. A compare of the
test_tableto thetest_table_delshows the same difference as above.
I dumped the slave and master binary log with:
./mysql-5.6.42-linux-glibc2.12-x86_64/bin/mysqlbinlog \
--no-defaults \
--set-charset=utf8mb4 \
--base64-output=decode-rows \
--verbose \
/path/to/mysql-bin-changelog.NNNNNN
On the slave's ROW binlog, for the key rows changing test_ghost.test_table, I see:
# at 135553
#181029 1:07:25 server id 1879241316 end_log_pos 135620 CRC32 0xf4be343c Table_map: `test_ghost`.`test_table` mapped to number 1410
# at 135620
#181029 1:07:25 server id 1879241316 end_log_pos 135689 CRC32 0xd5a24b62 Delete_rows: table id 1410 flags: STMT_END_F
### DELETE FROM `test_ghost`.`test_table`
### WHERE
### @1='\x11\377\377\377\377\377\377\377\377\377\377\377\377\377\377'
### @2='item 1'
### @3='\x11\377\377\377\377\377\377\377'
# at 135689
#181029 1:07:25 server id 1879241316 end_log_pos 135720 CRC32 0x045e1201 Xid = 3491148
COMMIT/*!*/;
# at 135720
#181029 1:07:25 server id 1879241316 end_log_pos 135798 CRC32 0xaffbabb7 Query thread_id=4947 exec_time=0 error_code=0
SET TIMESTAMP=1540775245/*!*/;
BEGIN
/*!*/;
# at 135798
#181029 1:07:25 server id 1879241316 end_log_pos 135865 CRC32 0x7728f223 Table_map: `test_ghost`.`test_table` mapped to number 1410
# at 135865
#181029 1:07:25 server id 1879241316 end_log_pos 135971 CRC32 0xdf24d1dc Update_rows: table id 1410 flags: STMT_END_F
### UPDATE `test_ghost`.`test_table`
### WHERE
### @1='"\377\377\377\377\377\377\377\377\377\377\377\377\377\377'
### @2='item 2'
### @3='"\377\377\377\377\377\377\377'
### SET
### @1='"\377\377\377\377\377\377\377\377\377\377\377\377\377\377'
### @2='item 2++'
### @3='"\377\377\377\377\377\377\377'
# at 135971
#181029 1:07:25 server id 1879241316 end_log_pos 136002 CRC32 0xc507994b Xid = 3491150
COMMIT/*!*/;
On the master's MIXED binlog, for the key rows changing test_ghost.test_table_gho, I see:
# at 150176
#181029 1:07:26 server id 1879241316 end_log_pos 150401 CRC32 0x1de6ff71 Query thread_id=4943 exec_time=0 error_code=0
SET TIMESTAMP=1540775246/*!*/;
delete /* gh-ost `test_ghost`.`_test_table_gho` */
from
`test_ghost`.`_test_table_gho`
where
((`id` = '\021\377\377\377\377\377\377\377\377\377\377\377\377\377\377'))
/*!*/;
# at 150401
#181029 1:07:26 server id 1879241316 end_log_pos 150696 CRC32 0x21b0348e Query thread_id=4943 exec_time=0 error_code=0
SET TIMESTAMP=1540775246/*!*/;
update /* gh-ost `test_ghost`.`_test_table_gho` */
`test_ghost`.`_test_table_gho`
set
`id`='\"\377\377\377\377\377\377\377\377\377\377\377\377\377\377', `info`='item 2++', `data`='\"\377\377\377\377\377\377\377'
where
((`id` = '\"\377\377\377\377\377\377\377\377\377\377\377\377\377\377'))
/*!*/;
(Note: I changed the actual binary values above to the four character sequence '\377' for readability. Otherwise putting this into github was converting them to '???????????????'.)
Note in the above the id keys used are, in hex, are X'11FFFFFFFFFFFFFFFFFFFFFFFFFFFF' for the DELETE, and X'22FFFFFFFFFFFFFFFFFFFFFFFFFFFF' which are both 15 bytes long, not 16 bytes. The WHERE condition fails to match in both statements, and the DELETE and UPDATE change nothing in the ghost table.