MySQL 8.0.1 introduced a work with replication threads mutexes in order to improve performance. In MySQL 8.0.2 the same work was extended, focusing in usability, and revamped how replication deals with disk-full conditions, improving the responsiveness of both monitoring commands and administrative commands such as KILL, as well as making status messages much more precise and helpful.
Before this work, a troubleshooting session may look like:
Operator 1
Operator 2
Operator 2 connects to the MySQL instance.
Operator 2
Operator 2 queries performance_schema.replication_connection_status table.
Operator 2
Operator 1
Operator 2 connects a new client session and queries performance_schema.threads table.
Operator 2
Operator 2
Operator 1
Operator 2
Operator 2 connects to the server host to check the MySQL instance error log.
Operator 2
Operator 1
The above could happen because when the replication receiver thread gets disk full while writing new events into the relay log, the server goes to a loop where it polls the disk every 60 seconds to see if enough space has been freed. It used to hold a mutex while doing so, and that prevented queries into performance_schema.replication_connection_* tables (and other monitoring statements like SHOW SLAVE STATUS) from executing.
Checking replication threads statuses also gave almost no clue about what was happening:
|
1
2
3
4
5
6
7
8
9
|
slave57> USE performance_schema; slave57> SELECT name, processlist_state, processlist_time FROM threads WHERE name LIKE '%slave%'; +----------------------+----------------------------------------+------------------+ | name | processlist_state | processlist_time | +----------------------+----------------------------------------+------------------+ | thread/sql/slave_io | Queueing master event to the relay log | 106 | | thread/sql/slave_sql | Reading event from the relay log | 120 | +----------------------+----------------------------------------+------------------+ 2 rows in set (0,00 sec) |
The only effective hint about the disk space issue was a set of messages into the server error log like:
|
1
2
|
[ERROR] [000000] Disk is full writing './slave-relay-bin.000002' (Errcode: 28 - No space left on device). Waiting for someone to free space... [ERROR] [000000] Retry in 60 secs. Message reprinted in 600 secs |
Trying to kill the receiver thread would make the server send the kill signal to the process, but the signal would only be checked by the thread when it was actually checking for disk space. So, as it slept for 60 seconds between attempts, the receiver thread sometimes waited up to 1 minute before being actually killed.
Also, when killed, the receiver thread left any event’s partial content already written into the relay log. Trying to show the contents of the relay log (using mysqlbinlog client program) would lead to an error reading the last (incomplete) event in the relay log file. In 5.7 (since 8.0.1 this should not happen), this partial content would lead to a SQL thread error:
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
|
slave57> USE performance_schema; slave57> SELECT * FROM replication_connection_status\G *************************** 1. row *************************** CHANNEL_NAME: GROUP_NAME: SOURCE_UUID: cb3480c2-adc5-11e7-bb36-b86b232ba6ca THREAD_ID: NULL SERVICE_STATE: OFF COUNT_RECEIVED_HEARTBEATS: 0 LAST_HEARTBEAT_TIMESTAMP: 0000-00-00 00:00:00 RECEIVED_TRANSACTION_SET: cb3480c2-adc5-11e7-bb36-b86b232ba6ca:1-7 LAST_ERROR_NUMBER: 1595 LAST_ERROR_MESSAGE: Relay log write failure: could not queue event from master LAST_ERROR_TIMESTAMP: 2017-10-10 15:19:15 1 row in set (0,01 sec) slave57> SELECT * FROM replication_applier_status_by_worker\G *************************** 1. row *************************** CHANNEL_NAME: WORKER_ID: 0 THREAD_ID: NULL SERVICE_STATE: OFF LAST_SEEN_TRANSACTION: cb3480c2-adc5-11e7-bb36-b86b232ba6ca:8 LAST_ERROR_NUMBER: 1594 LAST_ERROR_MESSAGE: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, or a bug in the master's or slave's MySQL code. If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave. LAST_ERROR_TIMESTAMP: 2017-10-10 15:19:15 1 row in set (0,00 sec) |
Improved usability
In MySQL 8.0.2 we introduced an improvement where the receiver thread no longer holds the mutex required for monitoring activities while writing into the relay log.
This means that, when blocked waiting for disk space, the receiver thread no longer blocks monitoring threads.
In order to allow operators to know what is happening without the need of inspecting server error log, the receiver thread will now state that it is waiting for disk space in any place showing replication thread states.
|
1
2
3
4
5
6
7
8
9
|
slave80> USE performance_schema; slave80> SELECT name, processlist_state, processlist_time FROM threads WHERE name LIKE '%slave%'; +----------------------+--------------------------------------------------------+------------------+ | name | processlist_state | processlist_time | +----------------------+--------------------------------------------------------+------------------+ | thread/sql/slave_io | Waiting for disk space | 28 | | thread/sql/slave_sql | Slave has read all relay log; waiting for more updates | 44 | +----------------------+--------------------------------------------------------+------------------+ 2 rows in set (0,38 sec) |
We also changed the wait for disk space procedure to check for the kill signal every second (freed disk space is still checked every minute). So, a KILL of the receiver thread waiting for disk space will make it stop almost promptly (no need to wait for up to a minute anymore). Also, when killed, the receiver thread will now truncate the relay log file in the end of the last completely received event (there will be no trash in the relay log file anymore).
|
1
2
3
4
|
[ERROR] Disk is full writing '/media/relay_log/slave-relay-bin.000004' (Errcode: 28 - No space left on device). Waiting for someone to free space... [ERROR] Retry in 60 secs. Message reprinted in 600 secs [ERROR] Slave I/O for channel '': Relay log write failure: failed to write event to the relay log file, Error_code: 1595 [Note] Relaylog file /media/relay_log/slave-relay-bin.000004 size was 1912832, but was truncated at 1904837. |
Conclusion
When you don’t know exactly what is happening with replication threads, it takes longer to identify the effective actions to fix the issue, which leads to further replication delays or incorrect actions that don’t deal with the problem. We have now improved the usability of commands to monitor replication threads, allowing a receiver thread to report that it is waiting for disk space as a thread state, and also allowing replication monitoring commands to not be blocked while the receiver thread is waiting for disk space. Time to update monitoring procedures!
Another day, in an operations room with MySQL 8…
Operator 1
Operator 2
Operator 2 connects to the MySQL instance and checks replication threads statuses.
Operator 2
Operator 1