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…..

Comments are closed.

Post Navigation