现象说明:
mysql5.1.45在做数据时,我重新将从库挂到主从中同步一段时间后出现如下现象
Connect_Retry: 60
Master_Log_File: mysql-bin.006727
Read_Master_Log_Pos: 1046964355
Relay_Log_File: relay-log.023103
Relay_Log_Pos: 1046964441
Relay_Master_Log_File: mysql-bin.006727
Slave_IO_Running: No
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table: mysql.%,test.%
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 1046964296
Relay_Log_Space: 1046965507
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: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 1236
Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'binlog truncated in the middle of event'
解决:
明显的说binlog被截断了,就去看1046964296这个点到底是在干嘛,查看如下:
# at 1046964296
#130702 0:47:10 server id 1207403942 end_log_pos 1046964355 Query thread_id=3340777569 exec_time=342 error_code=0
SET TIMESTAMP=1372697230/*!*/;
BEGIN
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
这是在mysql-bin.006727 的最后一个地方,显示开启了一个事务,但是事务没有继续往后执行,我的max_binlog_size设置的1.1G,mysql官网也有说明,当binlog最后遇到一个大事务时也会将日志记录在这个日志,而不会跨binlog记录一个事务,我继续看mysql-bin.006728 binlog的开头;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#130702 0:47:17 server id 4185257279 end_log_pos 106 Start: binlog v 4, server v 5.1.45-log created 130702 0:47:17
BINLOG '
lbLRUQ8/9XX5ZgAAAGoAAAAAAAQANS4xLjQ1LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
# at 106
#130702 0:53:02 server id 4185257279 end_log_pos 185 Query thread_id=46578159 exec_time=0 error_code=0
SET TIMESTAMP=1372697582/*!*/;
SET @@session.pseudo_thread_id=46578159/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 185
#130702 0:53:02 server id 4185257279 end_log_pos 5983 Query thread_id=46578159 exec_time=0 error_code
=0
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
.....................
mysql-bin.006728这个日志的开头也没有说明是继续上一个biblog的最后一个事务的,而是重新开启了一个事务;
于是我怀疑是不是记录binlog出错有部分操作没有计入进去;
就想法测试了一下,重新同步到mysql-bin.006728日志的开头,ok,一切没有问题,同步继续执行,知道执行完毕,此时我开始校验数据,数据也完全一致,说明不可能是mysql 没有记录部分binlog 操作,只说明记录mysql-bin.006727最后记录出错,但是这个出错没有影响到数据;
在使用MySQL 5.1.45时,主从同步过程中遇到binlog日志在事件中间被截断的问题,导致Slave_IO_Running为No。通过检查发现,binlog文件mysql-bin.006727的最后一个事务开启但未完成。进一步分析mysql-bin.006728,发现并非继续前一个binlog的事务,而是从新的事务开始。通过重新从mysql-bin.006728的开头同步,数据校验一致,说明数据未受影响,只是binlog记录出现错误。
316

被折叠的 条评论
为什么被折叠?



