关于Raplication之大惑

weichongli

有Master-Slave结构Mysql，以前一直同步正常。

最近经常出现很怪异的问题：

mysql> show slave status\G
*************************** 1. row ***************************
             Slave_IO_State: Waiting for master to send event
                Master_Host: 192.168.1.1
                Master_User: dbuser
                Master_Port: 3306
              Connect_Retry: 60
            Master_Log_File: mysql-bin.000193
        Read_Master_Log_Pos: 257898263
             Relay_Log_File: Db-relay-bin.000601
              Relay_Log_Pos: 257898400
      Relay_Master_Log_File: mysql-bin.000193
           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: 257898263
            Relay_Log_Space: 257898400
            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: 0
1 row in set (0.00 sec)

1秒种之后，再执行show slave status\G，结果如下

mysql> show slave status\G
*************************** 1. row ***************************
             Slave_IO_State: Waiting for master to send event
                Master_Host: 192.168.1.1
                Master_User:dbuser
                Master_Port: 3306
              Connect_Retry: 60
            Master_Log_File: mysql-bin.000193
        Read_Master_Log_Pos: 257903732
             Relay_Log_File: Db-relay-bin.000601
              Relay_Log_Pos: 257901335
      Relay_Master_Log_File: mysql-bin.000193
           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: 257901198
            Relay_Log_Space: 257903869
            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: 167
1 row in set (0.00 sec)

这也变的太快了吧？上一秒还是正常的，下一秒就落后Master服务器167秒了？？

为什么会这样？Seconds_Behind_Master的值是怎么计算出来的？

helbreathszw

你有my.cnf文件吗？
我瞧瞧

helbreathszw

应该是说master执行的延迟,可能是你们的数据量太多了。

weichongli

原帖由 helbreathszw 于 2007-5-11 16:51 发表
你有my.cnf文件吗？
我瞧瞧

master的还是slave的？

helbreathszw

你发我信箱好了szw2001@gmail.com
是master和slave的my.cnf,可能是你们做了什么delay延迟的

weichongli

原帖由 helbreathszw 于 2007-5-11 16:54 发表
应该是说master执行的延迟,可能是你们的数据量太多了。

数据量确实很大。

但让人摸不到头绪的是：上一秒执行show slave status\G，显示
      Seconds_Behind_Master: 0，也就是说，SLAVE与MASTER是即时同步的
仅仅过了一秒就
      Seconds_Behind_Master: 167，SLAVE上仅过了一秒，在MASTER上居然已经过了167秒，显得有点荒唐。

过几秒又显示为0……如此反复，折腾死我了（有个定期的监控脚本去检查这个数值，高于15秒就会邮件短信一起来骚扰我）

      “Seconds_Behind_Master”这个值是怎么算出来的？太荒唐了。

补充下：两台机器曾经在系统时间上相差了几分钟，但是后来用ntpdate校准成一样的了，这有可能是干扰因素吗？

helbreathszw

`Slave_IO_State' and `Seconds_Behind_Master' columns to the
     output of `SHOW SLAVE STATUS'.  `Slave_IO_State' indicates the
     state of the slave I/O thread, and `Seconds_Behind_Master'
     indicates the number of seconds by which the slave is late
     compared to the master.

weichongli

原帖由 helbreathszw 于 2007-5-11 17:01 发表
你发我信箱好了
是master和slave的my.cnf,可能是你们做了什么delay延迟的

已发，3Q

weichongli

原帖由 helbreathszw 于 2007-5-11 17:08 发表
`Slave_IO_State' and `Seconds_Behind_Master' columns to the
     output of `SHOW SLAVE STATUS'.  `Slave_IO_State' indicates the
     state of the slave I/O thread, and `Seconds_Behind_Master'
   ...

那Seconds_Behind_master这个值是怎么算的？
是当前Master的时间与SLAVE正在处理的日志所处的时间的差吗？
还是其它方法？

helbreathszw

Apparently on some systems tmp can be <0. Here are possible reasons
        related to MySQL:
        - the master is itself a slave of another master whose time is ahead.
        - somebody used an explicit SET TIMESTAMP on the master.
        Possible reason related to granularity-to-second of time functions
        (nothing to do with MySQL), which can explain a value of -1:
        assume the master's and slave's time are perfectly synchronized, and
        that at slave's connection time, when the master's timestamp is read,
        it is at the very end of second 1, and (a very short time later) when
        the slave's timestamp is read it is at the very beginning of second
        2. Then the recorded value for master is 1 and the recorded value for
        slave is 2. At SHOW SLAVE STATUS time, assume that the difference
        between timestamp of slave and rli->last_master_timestamp is 0
        (i.e. they are in the same second), then we get 0-(2-1)=-1 as a result.
        This confuses users, so we don't go below 0: hence the max().

        last_master_timestamp == 0 (an "impossible" timestamp 1970) is a
        special marker to say "consider we have caught up".