![variable.jp [データベース,パフォーマンス,運用]](https://variable.jp/wp-content/uploads/2013/09/cropped-variable.jp_.jpg)
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…..