Thu, 2014-10-02 17:25kolbekegel
MySQL 5.6 introduces a new "multi-threaded slave" feature (aka
"parallel replication") that turns the "slave SQL thread" into a
number of distinct threads that each apply events to different
schemas. This means that separate slave "worker threads" will be
executing different positions in the slave's relay log
(corresponding, of course, to different positions in the master's
binary log) and that the Relay_Master_Log_File and
Exec_Master_Log_Pos values in SHOW SLAVE
STATUS output are no longer an accurate indicator of the
current position of the slave. This causes severe problems if
using Percona XtraBackup/innobackupex with the
--slave-info option to get a backup that can be used
to seed a new slave. Let's take a look at how multi-threaded
slave works in MySQL 5.6, how innobackupex gets
position information, how to recognize problems, and how to work
around them to get a consistent backup that can be used for
seeding a new slave.
When a MySQL 5.6 slave is started with
slave_parallel_workers set great than 0 (the
default), you can identify the additional worker threads in
SHOW PROCESSLIST output. Here's an example with
slave_parallel_workers=3:
mysql> show processlist; +----+-------------+-----------+------+---------+------+-----------------------------------------------------------------------------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+-------------+-----------+------+---------+------+-----------------------------------------------------------------------------+------------------+ | 1 | root | localhost | NULL | Query | 0 | init | show processlist | | 27 | system user | | NULL | Connect | 4 | Waiting for master to send event | NULL | | 28 | system user | | NULL | Connect | 4 | Slave has read all relay log; waiting for the slave I/O thread to update it | NULL | | 29 | system user | | NULL | Connect | 4 | Waiting for an event from Coordinator | NULL | | 30 | system user | | NULL | Connect | 4 | Waiting for an event from Coordinator | NULL | | 31 | system user | | NULL | Connect | 4 | Waiting for an event from Coordinator | NULL | +----+-------------+-----------+------+---------+------+-----------------------------------------------------------------------------+------------------+ 6 rows in set (0.00 sec)
Thread 1 is the thread executing SHOW FULL
PROCESSLIST, thread 27 is the slave IO thread, thread 28
is what would traditionally be the "slave SQL thread", known in
the context of parallel replication as the "Coordinator", and
threads 29, 30, and 31 are the slave "worker" threads, the
threads that actually execute events on the slave.
The multi-threaded slave feature in MySQL 5.6 works by segragating traffic by schema. That is, queries/transactions affecting separate schemas can be handled by different worker threads. I've created two schemas ("db1" and "db2"), each of which has a table "t1" with a single auto-increment primary key column:
CREATE TABLE `t1` ( `id` int(10) unsigned NOT NULL AUTO_INCREMENT, PRIMARY KEY (`id`) ) ENGINE=InnoDB
I am executing two simple bash commands that insert rows into those two tables:
{ while :; do printf 'INSERT INTO t1 () VALUES ();\n'; done; } |
./bin/mysql --defaults-file=master.cnf db1 &
{ while :; do printf 'INSERT INTO t1 () VALUES ();\n'; done; } |
./bin/mysql --defaults-file=master.cnf db2 &
I'm using relay_log_info_repository=TABLE to make it
more easy to see what is happening with each of the worker
threads. When using the table-based relay log info repository,
you can consult mysql.slave_worker_info for
information about the state of each of the worker threads:
mysql> select * from mysql.slave_worker_info\G
*************************** 1. row ***************************
Id: 1
Relay_log_name:
Relay_log_pos: 0
Master_log_name:
Master_log_pos: 0
Checkpoint_relay_log_name:
Checkpoint_relay_log_pos: 0
Checkpoint_master_log_name:
Checkpoint_master_log_pos: 0
Checkpoint_seqno: 0
Checkpoint_group_size: 64
Checkpoint_group_bitmap:
*************************** 2. row ***************************
Id: 2
Relay_log_name: ./db1-relay-bin.000007
Relay_log_pos: 685319
Master_log_name: db1-bin.000005
Master_log_pos: 38233290
Checkpoint_relay_log_name: ./db1-relay-bin.000007
Checkpoint_relay_log_pos: 617615
Checkpoint_master_log_name: db1-bin.000005
Checkpoint_master_log_pos: 38165586
Checkpoint_seqno: 363
Checkpoint_group_size: 64
Checkpoint_group_bitmap: ...
*************************** 3. row ***************************
Id: 3
Relay_log_name: ./db1-relay-bin.000007
Relay_log_pos: 685505
Master_log_name: db1-bin.000005
Master_log_pos: 38233476
Checkpoint_relay_log_name: ./db1-relay-bin.000007
Checkpoint_relay_log_pos: 617615
Checkpoint_master_log_name: db1-bin.000005
Checkpoint_master_log_pos: 38165586
Checkpoint_seqno: 364
Checkpoint_group_size: 64
Checkpoint_group_bitmap: ...
3 rows in set (0.01 sec)
I executed that query after traffic to the master had been
stopped. Here are the relevant parts of the corresponding
SHOW SLAVE STATUS output:
mysql> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 127.0.0.1
Master_User: root
Master_Port: 4001
Connect_Retry: 60
Master_Log_File: db1-bin.000005
Read_Master_Log_Pos: 38233476
Relay_Log_File: db1-relay-bin.000007
Relay_Log_Pos: 685505
Relay_Master_Log_File: db1-bin.000005
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Exec_Master_Log_Pos: 38233476
Relay_Log_Space: 685837
Seconds_Behind_Master: 0
Master_Server_Id: 1
Master_UUID: f13feb2c-441f-11e4-846c-0800273876d5
Master_Info_File: mysql.slave_master_info
1 row in set (0.00 sec)
We can see there that Exec_Master_Log_Pos is
38233476, which matches the value of Master_log_pos
for worker thread #3 that we got from
mysql.slave_worker_info. Worker thread #2, on the
other hand, has a value of 38233290, though, even though there's
no traffic coming from the master. Worker thread #1 isn't doing
anything; because I'm only working with only 2 databases, only 2
worker threads can be utilized. So why aren't both the active
worker threads at the same position? Let's look at the binary log
to find out.
Here's a snippet of the binary log starting from the transaction
that ends at the position of worker thread #2 (38233290) until
the position shown by worker thread #3 and
Exec_Master_Log_Pos (38233476):
# at 38233104 #140925 12:26:32 server id 1 end_log_pos 38233175 CRC32 0x2dde38dd Query thread_id=11 exec_time=0 error_code=0 SET TIMESTAMP=1411673192/*!*/; BEGIN /*!*/; # at 38233175 #140925 12:26:32 server id 1 end_log_pos 38233219 CRC32 0xf87580f7 Table_map: `db2`.`t1` mapped to number 77 # at 38233219 #140925 12:26:32 server id 1 end_log_pos 38233259 CRC32 0x08c61960 Write_rows: table id 77 flags: STMT_END_F BINLOG ' aGwkVBMBAAAALAAAAINkRwIAAE0AAAAAAAEAA2RiMgACdDEAAQMAAPeAdfg= aGwkVB4BAAAAKAAAAKtkRwIAAE0AAAAAAAEAAgAB//4ikQEAYBnGCA== '/*!*/; ### INSERT INTO `db2`.`t1` ### SET ### @1=102690 /* INT meta=0 nullable=0 is_null=0 */ # at 38233259 #140925 12:26:32 server id 1 end_log_pos 38233290 CRC32 0xb1314ada Xid = 205705 COMMIT/*!*/; # at 38233290 #140925 12:26:32 server id 1 end_log_pos 38233361 CRC32 0xbe4c8c21 Query thread_id=12 exec_time=0 error_code=0 SET TIMESTAMP=1411673192/*!*/; BEGIN /*!*/; # at 38233361 #140925 12:26:32 server id 1 end_log_pos 38233405 CRC32 0x69f53824 Table_map: `db1`.`t1` mapped to number 76 # at 38233405 #140925 12:26:32 server id 1 end_log_pos 38233445 CRC32 0xe7cc526f Write_rows: table id 76 flags: STMT_END_F BINLOG ' aGwkVBMBAAAALAAAAD1lRwIAAEwAAAAAAAEAA2RiMQACdDEAAQMAACQ49Wk= aGwkVB4BAAAAKAAAAGVlRwIAAEwAAAAAAAEAAgAB//7OkQEAb1LM5w== '/*!*/; ### INSERT INTO `db1`.`t1` ### SET ### @1=102862 /* INT meta=0 nullable=0 is_null=0 */ # at 38233445 #140925 12:26:32 server id 1 end_log_pos 38233476 CRC32 0x680a36cd Xid = 205706 COMMIT/*!*/; # at 38233476
The first transaction is operating on database db2 and the second is operating on database db1. Remember that parallel slave workers in MySQL 5.6 operate on different databases. That means that slave worker #2 will never see the 2nd transaction shown, because worker thread #2 isn't operating on the database in that transaction's table map. Thus, worker thread #2 will simply leap-frog over that transaction when there is more relay log to be applied.
The problem here comes when trying to grab a snapshot of the
state of the slave. When there is traffic coming to the
slave, one of the slave workers might be a couple events behind
the position reported by Exec_Master_Log_Pos in
SHOW SLAVE STATUS output at the time that
innobackupex executes FLUSH TABLES WITH READ
LOCK. In that case, relying on
Exec_Master_Log_Pos to give you a snapshot of the
slave's position will fail. Here's a demonstration of that:
mysql> flush tables with read lock;
Query OK, 0 rows affected (0.00 sec)
mysql> select Id, Master_log_name, Master_log_pos from mysql.slave_worker_info;
+----+-----------------+----------------+
| Id | Master_log_name | Master_log_pos |
+----+-----------------+----------------+
| 1 | | 0 |
| 2 | db1-bin.000010 | 2207196 |
| 3 | db1-bin.000010 | 2206266 |
+----+-----------------+----------------+
3 rows in set (0.00 sec)
mysql> show slave status\G
*************************** 1. row ***************************
...
Relay_Master_Log_File: db1-bin.000010
...
Exec_Master_Log_Pos: 2206638
SHOW SLAVE STATUS output reports
Exec_Master_Log_Pos of 2206638, slave worker #2
reports Master_log_pos of 2207196, and slave worker
#3 reports Master_log_pos of 2206266. None of them
match up!
Here's the binlog snippet from the beginning of the event that
ends at the position reported by worker thread #3, the lowest of
the three positions we see, 2206266. The snippet goes through the
position of worker thread #2, the highest position value, at
2207196. The text for the highest and lowest positions should be
red and the text for the middle number reported by SHOW
SLAVE STATUS should be blue.
#140930 17:40:19 server id 1 end_log_pos 2206151 CRC32 0x0b522e06 Query thread_id=3 exec_time=0 error_code=0 SET TIMESTAMP=1412124019/*!*/; BEGIN /*!*/; # at 2206151 #140930 17:40:19 server id 1 end_log_pos 2206195 CRC32 0xe2d479fd Table_map: `db2`.`t1` mapped to number 71 # at 2206195 #140930 17:40:19 server id 1 end_log_pos 2206235 CRC32 0xee492a80 Write_rows: table id 71 flags: STMT_END_F BINLOG ' c00rVBMBAAAALAAAAPOpIQAAAEcAAAAAAAEAA2RiMgACdDEAAQMAAP151OI= c00rVB4BAAAAKAAAABuqIQAAAEcAAAAAAAEAAgAB//7rkhIAgCpJ7g== '/*!*/; ### INSERT INTO `db2`.`t1` ### SET ### @1=1217259 /* INT meta=0 nullable=0 is_null=0 */ # at 2206235 #140930 17:40:19 server id 1 end_log_pos 2206266 CRC32 0x3c27dd24 Xid = 11874 COMMIT/*!*/; # at 2206266 #140930 17:40:19 server id 1 end_log_pos 2206337 CRC32 0xe8d590b0 Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1412124019/*!*/; BEGIN /*!*/; # at 2206337 #140930 17:40:19 server id 1 end_log_pos 2206381 CRC32 0xe6622795 Table_map: `db1`.`t1` mapped to number 70 # at 2206381 #140930 17:40:19 server id 1 end_log_pos 2206421 CRC32 0xd573758f Write_rows: table id 70 flags: STMT_END_F BINLOG ' c00rVBMBAAAALAAAAK2qIQAAAEYAAAAAAAEAA2RiMQACdDEAAQMAAJUnYuY= c00rVB4BAAAAKAAAANWqIQAAAEYAAAAAAAEAAgAB//4rqBIAj3Vz1Q== '/*!*/; ### INSERT INTO `db1`.`t1` ### SET ### @1=1222699 /* INT meta=0 nullable=0 is_null=0 */ # at 2206421 #140930 17:40:19 server id 1 end_log_pos 2206452 CRC32 0xf9dc9029 Xid = 11875 COMMIT/*!*/; # at 2206452 #140930 17:40:19 server id 1 end_log_pos 2206523 CRC32 0x6450488d Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1412124019/*!*/; BEGIN /*!*/; # at 2206523 #140930 17:40:19 server id 1 end_log_pos 2206567 CRC32 0x22709a74 Table_map: `db1`.`t1` mapped to number 70 # at 2206567 #140930 17:40:19 server id 1 end_log_pos 2206607 CRC32 0xb61b2645 Write_rows: table id 70 flags: STMT_END_F BINLOG ' c00rVBMBAAAALAAAAGerIQAAAEYAAAAAAAEAA2RiMQACdDEAAQMAAHSacCI= c00rVB4BAAAAKAAAAI+rIQAAAEYAAAAAAAEAAgAB//4sqBIARSYbtg== '/*!*/; ### INSERT INTO `db1`.`t1` ### SET ### @1=1222700 /* INT meta=0 nullable=0 is_null=0 */ # at 2206607 #140930 17:40:19 server id 1 end_log_pos 2206638 CRC32 0x1719512d Xid = 11877 COMMIT/*!*/; # at 2206638 #140930 17:40:19 server id 1 end_log_pos 2206709 CRC32 0xdb47b048 Query thread_id=3 exec_time=0 error_code=0 SET TIMESTAMP=1412124019/*!*/; BEGIN /*!*/; # at 2206709 #140930 17:40:19 server id 1 end_log_pos 2206753 CRC32 0x90a42f1d Table_map: `db2`.`t1` mapped to number 71 # at 2206753 #140930 17:40:19 server id 1 end_log_pos 2206793 CRC32 0xe841042c Write_rows: table id 71 flags: STMT_END_F BINLOG ' c00rVBMBAAAALAAAACGsIQAAAEcAAAAAAAEAA2RiMgACdDEAAQMAAB0vpJA= c00rVB4BAAAAKAAAAEmsIQAAAEcAAAAAAAEAAgAB//7skhIALARB6A== '/*!*/; ### INSERT INTO `db2`.`t1` ### SET ### @1=1217260 /* INT meta=0 nullable=0 is_null=0 */ # at 2206793 #140930 17:40:19 server id 1 end_log_pos 2206824 CRC32 0x9cc8044e Xid = 11876 COMMIT/*!*/; # at 2206824 #140930 17:40:19 server id 1 end_log_pos 2206895 CRC32 0x056b4ff2 Query thread_id=3 exec_time=0 error_code=0 SET TIMESTAMP=1412124019/*!*/; BEGIN /*!*/; # at 2206895 #140930 17:40:19 server id 1 end_log_pos 2206939 CRC32 0x5136c994 Table_map: `db2`.`t1` mapped to number 71 # at 2206939 #140930 17:40:19 server id 1 end_log_pos 2206979 CRC32 0xaf308e76 Write_rows: table id 71 flags: STMT_END_F BINLOG ' c00rVBMBAAAALAAAANusIQAAAEcAAAAAAAEAA2RiMgACdDEAAQMAAJTJNlE= c00rVB4BAAAAKAAAAAOtIQAAAEcAAAAAAAEAAgAB//7tkhIAdo4wrw== '/*!*/; ### INSERT INTO `db2`.`t1` ### SET ### @1=1217261 /* INT meta=0 nullable=0 is_null=0 */ # at 2206979 #140930 17:40:19 server id 1 end_log_pos 2207010 CRC32 0x90f5f7dc Xid = 11878 COMMIT/*!*/; # at 2207010 #140930 17:40:19 server id 1 end_log_pos 2207081 CRC32 0xc9894ac6 Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1412124019/*!*/; BEGIN /*!*/; # at 2207081 #140930 17:40:19 server id 1 end_log_pos 2207125 CRC32 0x1ebe77c6 Table_map: `db1`.`t1` mapped to number 70 # at 2207125 #140930 17:40:19 server id 1 end_log_pos 2207165 CRC32 0x9257429d Write_rows: table id 70 flags: STMT_END_F BINLOG ' c00rVBMBAAAALAAAAJWtIQAAAEYAAAAAAAEAA2RiMQACdDEAAQMAAMZ3vh4= c00rVB4BAAAAKAAAAL2tIQAAAEYAAAAAAAEAAgAB//4tqBIAnUJXkg== '/*!*/; ### INSERT INTO `db1`.`t1` ### SET ### @1=1222701 /* INT meta=0 nullable=0 is_null=0 */ # at 2207165 #140930 17:40:19 server id 1 end_log_pos 2207196 CRC32 0xfed8fe65 Xid = 11879 COMMIT/*!*/; # at 2207196
The MySQL Reference Manual says this about about
Exec_Master_Log_Pos when using parallel
replication in MySQL 5.6:
When using a multi-threaded slave (by setting slave_parallel_workers to a nonzero value in MySQL 5.6.3 and later), the value in this column actually represents a “low-water” mark, before which no uncommitted transactions remain. Because the current implementation allows execution of transactions on different databases in a different order on the slave than on the master, this is not necessarily the position of the most recently executed transaction.
There are 6 transactions in that snippet. Indeed, all three
transactions before position 2206638 have been executed, one in
database db2 and two in database db1. But the problem here is
that worker thread #2, executing statements against db1, has
already progressed beyond this position and has executed another
event which ends at position 2207196. If you were to execute a
CHANGE MASTER TO statement with
MASTER_LOG_POS=2206638, which would be the
recommendation of innobackupex when using
--slave-info, you'd immediately hit a duplicate key
error when the transaction against db1 ending at position
#2207196 was executed again.
I filed a bug about this: innobackupex --slave-info doesn't handle slave_parallel_workers>0.
In the bug report, I originally proposed a complicated sequence
that would stop the slave, set
slave_parallel_workers back to 0, and start the
slave again. But there's an easier solution, and that's to use
the --safe-slave-backup option to
innobackupex. The --safe-slave-backup
causes innobackupex to execute STOP SLAVE
SQL_THREAD before getting the slave's replication
position.
When you execute STOP SLAVE SQL_THREAD on a slave
with slave_parallel_workers>0, the server waits
until the furthest-behind slave can catch up before the
STOP SLAVE command returns. At that time, it is safe
to trust Exec_Master_Log_Pos in SHOW SLAVE
STATUS output. Here are the relevant parts of
mysql.slave_worker_info and SHOW SLAVE
STATUS after executing STOP SLAVE SQL_THREAD
on a slave that's receiving and executing replication events from
an active master:
mysql> stop slave;
Query OK, 0 rows affected (2.24 sec)
mysql> select Id, Master_log_name, Master_log_pos from mysql.slave_worker_info;
+----+-----------------+----------------+
| Id | Master_log_name | Master_log_pos |
+----+-----------------+----------------+
| 1 | | 0 |
| 2 | db1-bin.000010 | 3534678 |
| 3 | db1-bin.000010 | 3534864 |
+----+-----------------+----------------+
3 rows in set (0.00 sec)
mysql> show slave status\G
*************************** 1. row ***************************
Slave_IO_State:
Master_Host: 127.0.0.1
Master_User: root
Master_Port: 4001
Connect_Retry: 60
Master_Log_File: db1-bin.000010
Read_Master_Log_Pos: 8177610
Relay_Log_File: db1-relay-bin.000009
Relay_Log_Pos: 3535025
Relay_Master_Log_File: db1-bin.000010
Slave_IO_Running: No
Slave_SQL_Running: Yes
...
Exec_Master_Log_Pos: 3534864
...
I challenge readers to verify the safety of this technique on
their own using the same techniques I used above to view the
status of the slave worker threads, compare them to SHOW
SLAVE STATUS output, and correlate those with binary log
contents via mysqlbinlog.
If you're using slave_parallel_workers>0 along
with innobackupex --slave-info, you should use
innobackupex's --safe-slave-backup
option in order to get a consistent view of the slave's position
with respect to the master. If slave SQL thread downtime is
problematic for you, you should consider using a dedicated backup
slave. Remember that even --slave-info by itself
entails FLUSH TABLES WITH READ LOCK which will
result in some amount of downtime for the SQL thread. The
additional time to stop the slave SQL thread(s) is unlikely to be
considerably more drastic.
Tags: HowtoMySQLReplication About the Author Kolbe Kegel
Kolbe Kegel is a Principal Support Engineer. Kolbe has worked with MySQL since 2005, first at MySQL, later at Sun Microsystems after its acquisition of MySQL Inc., then at Oracle after its acquisition of Sun.