MySQL5.7までのSHOW SLAVE STATUSだけでは分からない事が多かったけど、MySQL8.0のSHOW SLAVE STATUSは少し改善されていた。
マスター側で負荷をかけて、スレーブの状態を確認した時にスレーブ側で”Systetm lock”という状態になっていて、詳細を確認する為にPerformance Schemaを確認してみた。
MySQL8.0からはPerformance_Schemaを確認しなくても”Slave_SQL_Running_State”で状態が確認出来るようになっている。
以下、MySQL8.0で確認したログですが、MySQL5.7では”System lock”だった状態が、MySQL8.0では”Applying batch of row changes (update)”になっています。
[admin@misc02 ~]$ cat repli_log | grep Slave_SQL_Running_State
Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
Slave_SQL_Running_State: Reading event from the relay log
Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
Slave_SQL_Running_State: Reading event from the relay log
Slave_SQL_Running_State: Reading event from the relay log
Slave_SQL_Running_State: Reading event from the relay log
Slave_SQL_Running_State: Applying batch of row changes (update)
Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
[admin@misc02 ~]$
詳細: WL#7364: RBR: Enhanced Applier Thread Progress Details
https://dev.mysql.com/worklog/task/?id=7364
以下、MySQL5.7のケース
マスター側でmysqlslapで負荷をかけると、スレーブ側がsystem lockになっている。
スレーブ側でトランザクション実行して、UPLOCKかけて参照しても、同じsystem lockになる。
これだと、I/O Threadに遅延が無いことは分かるが、Applier Threadの状態が良く分からない。
[ON MASTER] – MySQL5.7
root@localhost [REPLI]> show create table T_SLAP01\G *************************** 1. row *************************** Table: T_SLAP01 Create Table: CREATE TABLE `T_SLAP01` ( `ID` int(11) NOT NULL AUTO_INCREMENT, `n_time` varchar(30) DEFAULT NULL, `s_time` varchar(30) DEFAULT NULL, PRIMARY KEY (`ID`) ) ENGINE=InnoDB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8mb4 1 row in set (0.00 sec) root@localhost [REPLI]> [root@misc01 admin]# cat mysqlslap_exsisting_table.sh /usr/local/mysql/bin/mysqlslap -u root -p -S /tmp/mysql.sock --create-schema=REPLI --no-drop -c 10 -i 1000 -q 'INSERT INTO REPLI.T_SLAP01(n_time,s_time) values(now(3),sysdate(6))' [root@misc01 admin]# [root@misc01 admin]# ./mysqlslap_exsisting_table.sh Enter password: Benchmark Average number of seconds to run all queries: 0.046 seconds Minimum number of seconds to run all queries: 0.018 seconds Maximum number of seconds to run all queries: 0.135 seconds Number of clients running queries: 10 Average number of queries per client: 1 [root@misc01 admin]#
[ON SLAVE]
上記マスターで負荷をかけた場合の、スレーブ側の状態。 “System lock”という状態になっている。ただし、この状態はApplier Threadが止まっている訳では無く、何らかの処理を行っている状態の場合もある。
root@localhost [REPLI]> show processlist; show engine innodb status\G show slave status\G +-----+-----------------+--------------+-------+---------+------+----------------------------------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+-----------------+--------------+-------+---------+------+----------------------------------+------------------+ | 1 | system user | | NULL | Connect | 888 | Waiting for master to send event | NULL | | 2 | system user | | NULL | Connect | -1 | System lock | NULL | | 3 | event_scheduler | localhost | NULL | Daemon | 887 | Waiting on empty queue | NULL | | 13 | root | localhost | REPLI | Query | 0 | starting | show processlist | | 29 | admin | Labs01:44555 | mysql | Sleep | 3 | | NULL | | 763 | admin | Labs01:47755 | mysql | Sleep | 55 | | NULL | +-----+-----------------+--------------+-------+---------+------+----------------------------------+------------------+ 6 rows in set (0.00 sec) *************************** 1. row *************************** Type: InnoDB Name: Status: ===================================== 2018-03-23 15:32:58 0x7fcdb65f0700 INNODB MONITOR OUTPUT ===================================== <SNIP> ------------ TRANSACTIONS ------------ Trx id counter 756832 Purge done for trx's n:o < 756831 undo n:o < 0 state: running but idle History list length 11 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421997346109728, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421997346107904, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421997346106992, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421997346106080, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 756831, ACTIVE (PREPARED) 0 sec 3 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 2 MySQL thread id 2, OS thread handle 140521468139264, query id 69415 System lock <SNIP> -------------- ROW OPERATIONS -------------- 0 queries inside InnoDB, 0 queries in queue 0 read views open inside InnoDB Process ID=8340, Main thread ID=140522077779712, state: sleeping Number of rows inserted 31953, updated 30756, deleted 0, read 32044 72.99 inserts/s, 72.99 updates/s, 0.00 deletes/s, 72.99 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================ 1 row in set (0.01 sec) *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 192.168.56.113 Master_User: repl_user Master_Port: 3306 Connect_Retry: 60 Master_Log_File: mysql-bin.002848 Read_Master_Log_Pos: 59249068 Relay_Log_File: misc02-relay-bin.000766 Relay_Log_Pos: 12937379 Relay_Master_Log_File: mysql-bin.002848 Slave_IO_Running: Yes Slave_SQL_Running: Yes <SNIP> Master_Server_Id: 1 Master_UUID: 2dde009f-d4dc-11e4-b437-0800279cea3c Master_Info_File: mysql.slave_master_info SQL_Delay: 0 SQL_Remaining_Delay: NULL Slave_SQL_Running_State: System lock Master_Retry_Count: 86400 Master_Bind: <SNIP> 1 row in set (0.00 sec) root@localhost [REPLI]>
SlaveのPerfomance_Schemaの状態。
Replication SlaveのIDで確認してみると、statement/sql/beginという状態である事が分かる。
root@localhost [REPLI]> SELECT event_id, event_name, timer_wait, lock_time FROM performance_schema.events_statements_history_long WHERE thread_id = @sql_thread; +----------+---------------------+------------+-----------+ | event_id | event_name | timer_wait | lock_time | +----------+---------------------+------------+-----------+ | 10003 | statement/sql/begin | 175076000 | 0 | +----------+---------------------+------------+-----------+ 1 row in set (0.01 sec) root@localhost [REPLI]> SELECT event_name, count_star, sum_timer_wait FROM performance_schema.events_waits_summary_by_thread_by_event_name WHERE thread_id = @sql_thread AND sum_timer_wait > 0 ORDER BY sum_timer_wait DESC; +--------------------------------------+------------+----------------+ | event_name | count_star | sum_timer_wait | +--------------------------------------+------------+----------------+ | wait/io/table/sql/handler | 10002 | 52235951612404 | | wait/io/file/innodb/innodb_log_file | 20012 | 24423316510586 | | wait/io/file/sql/binlog | 10014 | 372515866246 | | wait/io/file/innodb/innodb_data_file | 29 | 158702658238 | | wait/io/file/sql/relaylog | 12641 | 144454610798 | | wait/io/file/sql/binlog_index | 30 | 62816598186 | | wait/lock/table/sql/handler | 10003 | 51676533966 | | wait/io/file/sql/misc | 3 | 116404090 | +--------------------------------------+------------+----------------+
SLAVE側のSystem Lockの状態はRelay Logの適用から発生するトランザクションでした。
備考:以下のように、スレーブ側で参照ロックをかけた場合の状況もSystem Lock。
補足:トランザクションでロックをかけたセッションで、SYSスキーマを利用した為、sys.innodb_lock_waitsの値がおかしい。
違うセッションであれば、sys.innodb_lock_waitsも問題無い。
上記はバグでは無いですが、分かり難いのでスクリプト変更しました。(MySQL8.0では利用出来ません)
https://bugs.mysql.com/file.php?id=26694&bug_id=72131
Please Enjoy Replication with MySQL8.0 soon…..