处理mysql复制故障一例

今天一个主从复制的服务器出现了问题，数据和主服务器不一样，但是复制进程是对的。开始我只看了复制进程，没有太注意，原始内容如下：

1. mysql> show slave status\G 
2. *************************** 1. row *************************** 
3.                Slave_IO_State: Waiting for master to send event 
4.                   Master_Host: 192.168.125.9 
5.                   Master_User: slave 
6.                   Master_Port: 9188 
7.                 Connect_Retry: 10 
8.               Master_Log_File: mysql-bin.000004 
9.           Read_Master_Log_Pos: 805036116 
10.                Relay_Log_File: localhost-relay-bin.000018 
11.                 Relay_Log_Pos: 192473825 
12.         Relay_Master_Log_File: mysql-bin.000004 
13.              Slave_IO_Running: Yes 
14.             Slave_SQL_Running: Yes 
15.               Replicate_Do_DB:  
16.           Replicate_Ignore_DB:  
17.            Replicate_Do_Table:  
18.        Replicate_Ignore_Table:  
19.       Replicate_Wild_Do_Table:  
20.   Replicate_Wild_Ignore_Table:  
21.                    Last_Errno: 0 
22.                    Last_Error:  
23.                  Skip_Counter: 0 
24.           Exec_Master_Log_Pos: 197587108 
25.               Relay_Log_Space: 805036869 
26.               Until_Condition: None 
27.                Until_Log_File:  
28.                 Until_Log_Pos: 0 
29.            Master_SSL_Allowed: No 
30.            Master_SSL_CA_File:  
31.            Master_SSL_CA_Path:  
32.               Master_SSL_Cert:  
33.             Master_SSL_Cipher:  
34.                Master_SSL_Key:  
35.         Seconds_Behind_Master: 25236 
36. Master_SSL_Verify_Server_Cert: No 
37.                 Last_IO_Errno: 0 
38.                 Last_IO_Error:  
39.                Last_SQL_Errno: 0 
40.                Last_SQL_Error:  
41. 1 row in set (0.00 sec) 

后来发现数据不对，发现

Read_Master_Log_Pos和Exec_Master_Log_Pos真么差别这么大，原理上，应该是挨着的， 然后开始找问题，把日志翻来覆去的看，没有发现任何问题，然后看了一下processlist： ，发现延迟了5个多小时，我的个娘耶。 

1. mysql> show processlist\G 
2. *************************** 1. row *************************** 
3.      Id: 1 
4.    User: root 
5.    Host: localhost 
6.      db: NULL 
7. Command: Query 
8.    Time: 0 
9.   State: NULL 
10.    Info: show processlist 
11. *************************** 2. row *************************** 
12.      Id: 2 
13.    User: system user 
14.    Host:  
15.      db: NULL 
16. Command: Connect 
17.    Time: 1038 
18.   State: Waiting for master to send event 
19.    Info: NULL 
20. *************************** 3. row *************************** 
21.      Id: 3 
22.    User: system user 
23.    Host:  
24.      db: NULL 
25. Command: Connect 
26.    Time: 18697
    
27.   State: freeing items 
28.    Info: NULL 
29. 3 rows in set (0.00 sec) 

基本确认主库和从库是延迟，而不是认为或者其他bug之类的东西。

开始找延迟的原因吧：

1、检查网络延时：

1. [root@localhost var]# ping 192.168.125.9 
2. PING 192.168.125.9 (192.168.125.9) 56(84) bytes of data. 
3. 64 bytes from 192.168.125.9: icmp_seq=1 ttl=64 time=0.555 ms 
4. 64 bytes from 192.168.125.9: icmp_seq=2 ttl=64 time=0.588 ms 
5. 64 bytes from 192.168.125.9: icmp_seq=3 ttl=64 time=0.635 ms 
6. 64 bytes from 192.168.125.9: icmp_seq=4 ttl=64 time=0.588 ms 
7. 64 bytes from 192.168.125.9: icmp_seq=5 ttl=64 time=0.586 ms 

没有发现问题。

2、检查系统资源

1. [root@localhost var]# iostat -dx 1 5 
2. Linux 2.6.18-164.el5PAE (localhost.localdomain)         11/18/2011 
3.  
4. Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
5. sda               0.07    40.80  0.22 123.53     6.06  1314.72    10.67     0.98    7.92   2.74  33.97 
6. sda1              0.01     0.00  0.00  0.00     0.02     0.00    18.93     0.00    2.33   1.60   0.00 
7. sda2              0.00     0.00  0.00  0.00     0.01     0.00    36.13     0.00    3.65   2.81   0.00 
8. sda3              0.02     0.01  0.00  0.01     0.02     0.16    20.21     0.00    5.36   2.71   0.00 
9. sda4              0.00     0.00  0.00  0.00     0.00     0.00     2.00     0.00   21.00  21.00   0.00 
10. sda5              0.04    40.79  0.22 123.52     6.01  1314.56    10.67     0.98    7.92   2.74  33.96 
11.  
12. Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
13. sda               0.00   156.00  2.00 365.00    16.00  4160.00    11.38     3.15    8.64   2.68  98.30 
14. sda1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
15. sda2              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
16. sda3              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
17. sda4              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
18. sda5              0.00   156.00  2.00 365.00    16.00  4160.00    11.38     3.15    8.64   2.68  98.30 
19.  
20. Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
21. sda               0.00   112.00  0.00 315.00     0.00  3448.00    10.95     2.52    8.06   3.13  98.70 
22. sda1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
23. sda2              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
24. sda3              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
25. sda4              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
26. sda5              0.00   112.00  0.00 315.00     0.00  3448.00    10.95     2.52    8.06   3.13  98.70 
27.  
28. Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
29. sda               0.00   103.96  0.00 195.05     0.00  2392.08    12.26     3.12   15.47   5.06  98.71 
30. sda1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
31. sda2              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
32. sda3              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
33. sda4              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
34. sda5              0.00   103.96  0.00 195.05     0.00  2392.08    12.26     3.12   15.47   5.06  98.71 

发现有IO，但是不太厉害，算正常。

然后看CPU，使用top命令

1. Tasks: 141 total,   1 running, 139 sleeping,   1 stopped,   0 zombie 
2. Cpu0  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st 
3. Cpu1  :  0.3%us,  0.3%sy,  0.0%ni, 99.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st 
4. Cpu2  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st 
5. Cpu3  :  0.0%us,  4.7%sy,  0.0%ni, 94.7%id,  0.0%wa,  0.0%hi,  0.7%si,  0.0%st 
6. Cpu4  :  0.0%us,  1.3%sy,  0.0%ni,  1.0%id, 97.3%wa,  0.3%hi,  0.0%si,  0.0%st 
7. Cpu5  :  0.0%us,  0.3%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st 
8. Cpu6  :  0.0%us,  0.0%sy,  0.0%ni, 91.3%id,  0.0%wa,  3.7%hi,  5.0%si,  0.0%st 
9. Cpu7  :  0.3%us,  7.0%sy,  0.0%ni, 81.8%id,  0.0%wa,  1.0%hi,  9.9%si,  0.0%st 
10. Mem:   4139196k total,  2605768k used,  1533428k free,   215052k buffers 
11. Swap:  8385920k total,        0k used,  8385920k free,  2143992k cached 

发现

Cpu4  :  0.0%us,  1.3%sy,  0.0%ni,  1.0%id, 97.3%wa,  0.3%hi,  0.0%si,  0.0%st  这个核有点问题 

wait太高的，话，应该是cpu在等待IO资源，导致的。 但是IO资源又不太高，才几M的写入。 不过现在也没办法，只有想法降低mysql的写入来试试看。  我关闭了slave更新bin-log的功能 #log-slave-updates  然后重启mysql，启动slave进程。现在Slave_SQL进程速度加快了，明显看见 Exec_Master_Log_Pos数增加，show processlist中的时间也在缩短， 过了有20多分钟，数据同步完成了。通过maatkit工具检查，没有问题。  故障现在是修复了，不过为什么mysql的IO那么低，却会导致IO资源缺乏，我尝试通过写文件来测试磁盘IO，应该可以达到130多M/s。 这个问题现在比较诡异了，估计是mysql slave只能使用单核导致的，而这台服务器虽然是8核的，但是单核的主频只有2.13，中继sql，执行sql，写入自己的blog，IO请求都在一个核上，导致的资源不足。

在补充一下，这个机器业务空闲后，我做了一个基准测试，发现效率还是上不去。找了硬件的原因，也怀疑过编译参数，在相同硬件平台和mysql版本做了相关测试。最后发现这次性能问题的最终杀手是my.cnf的一个配置。这次心血来潮加了如下一个参数

sync_binlog=1  //意思是即时同步binlog到硬盘上，不缓存日志，目的是避免硬件故障或者软件故障导致binlog没有即时写盘而丢失。但是开始没想到这个参数在QPS上到100左右后，性能消耗是如此的高，导致整个CPU核都在等待IO，建议大家以后不是特别需要，还是别碰这个参数了，默认是0，由操作系统来调度什么时候写入到硬盘，或者将值调整到比较大。

还有一个就是innodb引擎的

innodb_flush_log_at_trx_commit = N

N=0  – 每隔一秒，把事务日志缓存区的数据写到日志文件中，以及把日志文件的数据刷新到磁盘上；

N=1  – 每个事务提交时候，把事务日志从缓存区写到日志文件中，并且刷新日志文件的数据到磁盘上；

N=2  – 每事务提交的时候，把事务日志数据从缓存区写到日志文件中；每隔一秒，刷新一次日志文件，但不一定刷新到磁盘上，而是取决于操作系统的调度；

如果设置为1，效率也会相当的低，建议设置到2，如果想要性能再提交，可以设置为0.