处理mysql复制故障一例

唐伯虎

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

mysql> show slave status\G 
*************************** 1. row *************************** 
         Slave_IO_State: Waiting for master to send event 
          Master_Host: 192.168.125.9 
          Master_User: slave 
          Master_Port: 9188 
        Connect_Retry: 10 
        Master_Log_File: mysql-bin.000004 
      Read_Master_Log_Pos: 805036116 
         Relay_Log_File: localhost-relay-bin.000018 
        Relay_Log_Pos: 192473825 
    Relay_Master_Log_File: mysql-bin.000004 
       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: 197587108 
        Relay_Log_Space: 805036869 
        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: 25236 
Master_SSL_Verify_Server_Cert: No 
        Last_IO_Errno: 0 
        Last_IO_Error:  
         Last_SQL_Errno: 0 
         Last_SQL_Error:  
1 row in set (0.00 sec)

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

mysql> show processlist\G 
*************************** 1. row *************************** 
   Id: 1 
   User: root 
   Host: localhost 
   db: NULL 
Command: Query 
   Time: 0 
  State: NULL 
   Info: show processlist 
*************************** 2. row *************************** 
   Id: 2 
   User: system user 
   Host:  
   db: NULL 
Command: Connect 
   Time: 1038 
  State: Waiting for master to send event 
   Info: NULL 
*************************** 3. row *************************** 
   Id: 3 
   User: system user 
   Host:  
   db: NULL 
Command: Connect 
   Time: 18697
  State: freeing items 
   Info: NULL 
3 rows in set (0.00 sec)

　　基本确认主库和从库是延迟，而不是认为或者其他bug之类的东西。
　　开始找延迟的原因吧：
　　1、检查网络延时：

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

　　没有发现问题。
　　
2、检查系统资源

[root@localhost var]# iostat -dx 1 5 
Linux 2.6.18-164.el5PAE (localhost.localdomain)     11/18/2011 
 
Device:     rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
sda         0.07  40.80  0.22 123.53   6.06  1314.72  10.67   0.98  7.92   2.74  33.97 
sda1        0.01   0.00  0.00  0.00   0.02   0.00  18.93   0.00  2.33   1.60   0.00 
sda2        0.00   0.00  0.00  0.00   0.01   0.00  36.13   0.00  3.65   2.81   0.00 
sda3        0.02   0.01  0.00  0.01   0.02   0.16  20.21   0.00  5.36   2.71   0.00 
sda4        0.00   0.00  0.00  0.00   0.00   0.00   2.00   0.00   21.00  21.00   0.00 
sda5        0.04  40.79  0.22 123.52   6.01  1314.56  10.67   0.98  7.92   2.74  33.96 
 
Device:     rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
sda         0.00   156.00  2.00 365.00  16.00  4160.00  11.38   3.15  8.64   2.68  98.30 
sda1        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
sda2        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
sda3        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
sda4        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
sda5        0.00   156.00  2.00 365.00  16.00  4160.00  11.38   3.15  8.64   2.68  98.30 
 
Device:     rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
sda         0.00   112.00  0.00 315.00   0.00  3448.00  10.95   2.52  8.06   3.13  98.70 
sda1        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
sda2        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
sda3        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
sda4        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
sda5        0.00   112.00  0.00 315.00   0.00  3448.00  10.95   2.52  8.06   3.13  98.70 
 
Device:     rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
sda         0.00   103.96  0.00 195.05   0.00  2392.08  12.26   3.12   15.47   5.06  98.71 
sda1        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
sda2        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
sda3        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
sda4        0.00   0.00  0.00  0.00   0.00   0.00   0.00   0.00  0.00   0.00   0.00 
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命令

Tasks: 141 total,   1 running, 139 sleeping,   1 stopped,   0 zombie 
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 
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 
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 
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 
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 
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 
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 
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 
Mem:   4139196k total,  2605768k used,  1533428k free,   215052k buffers 
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.

具体可以参见如下文章：http://www.mysqlops.com/2011/10/26/mysql-variable-third.html