mysql主从同步从库写入缓慢

两台生产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  818mysql> 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   

解决方案 »

  1.   


    你看看那个一直100%的线程，是在运行某个sql吗
      

  2.   

    没有sql运行，show processlist ，只有一个 Reading event from the relay log
      

  3.   

    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                                    |
      

  4.   

    在出现 Reading event from the relay log  的时候  Exec_Master_Log_Pos 就会卡住，正过了又会恢复一会，然后又出现 Reading event from the relay log  ，这样往复。
      

  5.   

    查看 io_thread 是正常的，卡在 sql_thread ，主库上的所有binlog 都正常下载到本地，且都生成了rep_relay_log 。
    日志看没有异常，日志没有 error
      

  6.   

    没有大操作，看了binlog只有普通的dml操作。
      

  7.   

    Relay_Log_Space: 16153580669
    ---------------------------------------------   这个值算出来15GB，所以我觉得还是有大事务导致出问题
    这个文件的大小受限于 max_relay_log_size， 如果配置为0，则是取决于 max_binlog_size ，默认为1GB
    如果你没有修改过默认值，那么这个文件最大应该在1GB左右，除非有大事务，事务不会跨多个log文件，所以有超大事务会导致日志文件比限制值大很多
      

  8.   

    Relay_Log_Space这个是所有relay log大小总和   
      

  9.   

    relay log 默认是自动清理的，所以在没有改默认设置的情况下，这个不应该会太大
    如果有j时间和耐心，可以用 mysqlbinlog 查下 relay log 确认下
      

  10.   


    查看了binlog文件，没有发现大的事物操作，都是正常作业的 update 和insert 。可以看到有个线程（thread/innodb/srv_master_thread ）一直是 100% ，系统也一直显示 “Reading event from the relay log”
      

  11.   

    这个过程中调整过的参数：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”