兩臺生產linux主機做的主從，一直運行的很好，昨天突然運行出現巨大延遲，Exec_Master_Log_Pos 跳動一會后停止，過一會又動，就這樣往復。查看各個引數都顯示正常，之前沒有調整，但是現在 show processlist 里會出現 Reading event from the relay log ，這個狀態出現一會后消失，過一會又出現。磁盤IO 在調整了 sync_binlog =1 后有所提高,原來默認是 0 ， 在 io 寫很低的時候 Exec_Master_Log_Pos 就可能不變化，請大家幫忙看一下問題在哪里，多謝了。
innodb status 里會出現如下資訊：
MySQL thread id 10, query id 279129 Reading event from the relay log
或者：
7 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 5
詳細資訊如下：
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1 1_second, 1 sleeps, 0 10_second, 1 background, 0 flush
srv_master_thread log flush and writes: 23295
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1906101, signal count 1785575
。。。。
Mutex spin waits 110381692, rounds 277492261, OS waits 1637293
RW-shared spins 64196, rounds 883065, OS waits 13030
RW-excl spins 377665, rounds 8864472, OS waits 218680
Spin rounds per wait: 2.51 mutex, 13.76 RW-shared, 23.47 RW-excl
------------
------------
TRANSACTIONS
------------
Trx id counter 42B92CD79
Purge done for trx's n < 2E3D3C544 undo n < 0
History list length 1753661298
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started, process no 206656, OS thread id 139769784071936
MySQL thread id 6, query id 35655 127.0.0.1 root
show engine INNODB STATUS
---TRANSACTION 42B92CD78, ACTIVE 1 sec, process no 206656, OS thread id 139769783015168 inserting
mysql tables in use 2, locked 2
7 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 5
MySQL thread id 10, query id 35655
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
128661 OS file reads, 22408 OS file writes, 572 OS fsyncs
38.07 reads/s, 16414 avg bytes/read, 39.71 writes/s, 0.86 fsyncs/s
或者：
TRANSACTIONS
------------
Trx id counter 42B947192
Purge done for trx's n < 2E3FB5A47 undo n < 259
History list length 1753294784
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started, process no 206656, OS thread id 139769781958400
MySQL thread id 120, query id 279129 127.0.0.1 root
show engine INNODB STATUS
---TRANSACTION 42B947191, ACTIVE (PREPARED) 0 sec, process no 206656, OS thread id 139769783015168
2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1
MySQL thread id 10, query id 279129 Reading event from the relay log
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
224485 OS file reads, 136603 OS file writes, 3308 OS fsyncs
0.33 reads/s, 16384 avg bytes/read, 20.44 writes/s, 0.04 fsyncs/s
設定的引數如下：
+-------------------+--------------------+
| Variable_name | Value |
+-------------------+--------------------+
| max_tmp_tables | 32 |
| slave_load_tmpdir | /data-dsk/mysqltmp |
| tmp_table_size | 536870912 |
| tmpdir | /data-dsk/mysqltmp |
| ft_query_expansion_limit | 20 |
| have_query_cache | YES |
| long_query_time | 3.000000 |
| query_alloc_block_size | 8192 |
| query_cache_limit | 2097152 |
| query_cache_min_res_unit | 4096 |
| query_cache_size | 0 |
| query_cache_type | OFF |
| query_cache_wlock_invalidate | OFF |
| query_prealloc_size | 8192 |
| slow_query_log | ON |
| binlog_cache_size | 1048576 |
| binlog_direct_non_transactional_updates | OFF |
| binlog_format | MIXED |
| binlog_stmt_cache_size | 32768 |
| innodb_locks_unsafe_for_binlog | OFF |
| max_binlog_cache_size | 18446744073709547520 |
| max_binlog_size | 1073741824 |
| max_binlog_stmt_cache_size | 18446744073709547520 |
| sync_binlog | 1 |
+-------------------+--------------------+
磁盤IO 在調整了 sync_binlog =1 后有所提高,原來默認是 0 ， 在 io 寫很低的時候 Exec_Master_Log_Pos 就可能不變化
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read writ| recv send| in out | int csw
12 2 85 0 0 0| 23M 10M| 0 0 |8858B 13k|9401 35k
5 0 94 2 0 0|8192B 268k| 566k 553k| 0 0 |9062 904
4 0 93 2 0 0| 972k 260k| 680k 675k| 0 0 |9078 1092
4 0 95 1 0 0|4096B 96k|2163k 2171k| 0 0 | 23k 1166
5 0 95 0 0 0| 544k 7272k|6727k 6758k|8192B 0 | 25k 3557
4 0 93 2 0 0|8192B 348k|5035k 5287k| 0 0 |9239 1189
4 0 93 2 0 0| 24k 324k| 684k 734k| 0 0 | 13k 1312
5 0 93 2 0 0| 116k 324k|3260k 3272k| 0 0 | 15k 1170
4 0 93 2 0 0| 200k 840k|3221k 3540k| 0 0 | 11k 1174
4 0 95 1 0 0| 0 64k|1052k 1066k| 0 0 |8521 801
5 0 95 0 0 0| 0 60k| 642k 605k| 0 0 |8366 876
5 0 95 0 0 0| 0 56k| 666k 652k| 0 0 |9142 939
4 0 95 1 0 0| 60k 452k| 691k 677k| 0 0 | 11k 1191
7 1 92 0 0 0| 0 8192B| 997k 1090k| 0 0 | 11k 1339
5 0 95 0 0 0|4096B 8532k| 660k 631k| 0 0 | 12k 1980
4 0 96 0 0 0| 0 64k|2906k 3024k| 0 0 | 23k 765
4 0 96 0 0 0| 0 0 |6685k 6642k| 0 0 | 19k 749
4 0 96 0 0 0| 0 0 |3793k 3754k| 0 0 |9121 729
5 0 93 1 0 0| 32k 68k| 700k 663k| 0 0 | 13k 2067
5 0 95 0 0 0| 0 312k|4309k 4509k| 0 0 | 16k 1608
5 0 95 0 0 0|4096B 128k|3281k 3290k| 0 0 | 13k 953
4 0 96 0 0 0| 0 0 |1323k 1297k| 0 0 | 11k 911
5 0 95 0 0 0| 0 0 | 765k 703k| 0 0 | 11k 1190
4 0 95 0 0 0|4096B 68k| 773k 729k| 0 0 | 10k 1154
6 2 92 0 0 0|1012k 932k| 900k 981k| 20k 0 | 18k 5842
4 1 94 0 0 0|4096B 292k| 909k 953k| 0 0 | 12k 1624
4 0 96 0 0 0| 0 0 | 797k 746k| 0 0 | 13k 917
4 0 95 0 0 0| 0 112k|3545k 3505k| 0 0 | 23k 818
mysql> show slave status\G;
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: x.x.x.x
Master_User: slaver
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.006524
Read_Master_Log_Pos: 46913321
Relay_Log_File: rep_relay_log.003406
Relay_Log_Pos: 653699241
Relay_Master_Log_File: mysql-bin.006509
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 653699095
Relay_Log_Space: 16153580669
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 110932
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 603333
1 row in set (0.00 sec)
ERROR:
No query specified
查看執行緒，看到有一個執行緒的cpu一直是 100%
mysql 99.4 19 - - - - - - - 25903 - 23 0 thread/innodb/srv_master_thread
uj5u.com熱心網友回復：
你看看那個一直100%的執行緒，是在運行某個sql嗎
uj5u.com熱心網友回復：
沒有sql運行，show processlist ，只有一個 Reading event from the relay loguj5u.com熱心網友回復：
兩臺機器之間的網路是否正常uj5u.com熱心網友回復：
mysql> show processlist;+-----+-------------+--------------------+--------------------+---------+--------+----------------------------------+-----------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-----+-------------+--------------------+--------------------+---------+--------+----------------------------------+-----------------------------------------+
| 7 | system user | | NULL | Connect | 58267 | Waiting for master to send event | NULL |
| 8 | system user | | NULL | Connect | 217718 | Reading event from the relay log | NULL |
uj5u.com熱心網友回復：
網路正常，都是千兆網
uj5u.com熱心網友回復：
在出現 Reading event from the relay log 的時候 Exec_Master_Log_Pos 就會卡住，正過了又會恢復一會，然后又出現 Reading event from the relay log ，這樣往復。uj5u.com熱心網友回復：
從庫的錯誤日志有沒有例外uj5u.com熱心網友回復：
查看 io_thread 是正常的，卡在 sql_thread ，主庫上的所有binlog 都正常下載到本地，且都生成了rep_relay_log 。日志看沒有例外，日志沒有 error
uj5u.com熱心網友回復：
單事務中做了大量操作?uj5u.com熱心網友回復：
或者是單事務中的操作涉及大量資料？uj5u.com熱心網友回復：
沒有大操作，看了binlog只有普通的dml操作。uj5u.com熱心網友回復：
Relay_Log_Space: 16153580669--------------------------------------------- 這個值算出來15GB，所以我覺得還是有大事務導致出問題
這個檔案的大小受限于 max_relay_log_size， 如果配置為0，則是取決于 max_binlog_size ，默認為1GB
如果你沒有修改過默認值，那么這個檔案最大應該在1GB左右，除非有大事務，事務不會跨多個log檔案，所以有超大事務會導致日志檔案比限制值大很多
uj5u.com熱心網友回復：
Relay_Log_Space這個是所有relay log大小總和uj5u.com熱心網友回復：
relay log 默認是自動清理的，所以在沒有改默認設定的情況下，這個不應該會太大
如果有j時間和耐心，可以用 mysqlbinlog 查下 relay log 確認下
uj5u.com熱心網友回復：
查看了binlog檔案，沒有發現大的事物操作，都是正常作業的 update 和insert 。可以看到有個執行緒（thread/innodb/srv_master_thread ）一直是 100% ，系統也一直顯示 “Reading event from the relay log”
uj5u.com熱心網友回復：
這個程序中調整過的引數：query_cache_type = 0 和 query_cache_size = 0 、sync_binlog=1 都沒有好轉，會走但是就是非常緩慢。這個實體還有個奇怪的現象當打開 query_cache_type = 1 時，就會報“ invalidating query cache entries (table) ”， 消除了這個后就長顯示 “Reading event from the relay log”uj5u.com熱心網友回復：
樓主問題解決了嗎？uj5u.com熱心網友回復：
請問樓主問題解決了嗎？我這邊也發生了這樣的現象。uj5u.com熱心網友回復：
存盤有沒有問題呀uj5u.com熱心網友回復：
這個應該是SQL_THREAD執行時的問題，可能是insert或update操作了大量的資料，或者，類似操作性能很差，可以看看正在做的操作，然后，確定原因和解決方法。轉載請註明出處，本文鏈接：https://www.uj5u.com/shujuku/26658.html
標籤：MySQL
上一篇：關于excel表匯入資料庫的問題
下一篇：Mysql匯入資料報io例外