上周末和开发人员对线上库中的部分表的在线DDL和update,这过程中出现了一些意料之外的问题,现将过程、分析和解决方案在这里总结一下
一、 需求背景:
要在如下表中添加字段(modified_at)并且更改默认值
table_name {
baby_comp
baby_comp_status
baby_usr
baby_ad_user
baby_camp
baby_ord
baby_acc_eva
}
每张表执行如下操作
ALTER TABLE `$table_name` ADD COLUMN `modified_at` TIMESTAMP DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP COMMENT '创建时间/最后修改时间'");
更新的语句
UPDATE `baby_camp`
SET `modified_at` = FROM_UNIXTIME(updated_time + 60)
WHERE `modified_at` <= '1970-01-01 08:00:00';
二、 数据库架构
master:192.168.100.18 >主库写数据复制源
slave1:192.168.100.17 >搜索用
slave2:192.168.100.19 >查询用
slave3:192.168.100.10 >查询用
slave4:192.168.100.15 >备份用
三、故障的相关信息截取:
问题 1. max binlog cache 不足引起的复制崩溃 涉及从库(192.168.100.17-搜索用 和 192.168.100.15-备份用)
161009 21:42:49 [ERROR] Slave SQL: Could not execute Write_rows event on table baby.baby_delta; Multi-statement transaction required more than 'max_binlog_cache_size' bytes of storage; increase this MySQLd variable and try again, Error_code: 1197; Writing one row to the row-based binary log failed, Error_code: 1534; handler error HA_ERR_RBR_LOGGING_FAILED; the event's master log mysql-bin.007759, end_log_pos 3856759100, Error_code: 1197
161009 21:42:49 [Warning] Slave: Multi-statement transaction required more than 'max_binlog_cache_size' bytes of storage; increase this mysqld variable and try again Error_code: 1197
161009 21:42:49 [Warning] Slave: Writing one row to the row-based binary log failed Error_code: 1534
161009 21:42:49 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.007759' position 633959791
161009 21:43:48 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
161009 21:43:48 [Note] Slave I/O thread killed while reading event
161009 21:43:48 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.007760', position 301659
161009 21:43:53 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.007759' at position 633959791, relay log './serverdb01-relay-bin.009618' position: 633959937
161009 21:43:53 [Note] Slave I/O thread: connected to master 'backup@192.168.100.18:3306',replication started in log 'mysql-bin.007760' at position 301659
++++
解释:
报错主要是:从库上对于表baby.baby_delta的操作不能写到binlog中,多语句的事物请求更多的max_binlog_cache_szie,增加max_binlog_cache_szie大小重试
++++
问题 2. max allowed packet 不足引起的复制崩溃 涉及从库(192.168.100.15-备份用)
161009 21:42:49 [ERROR] Error reading packet from server: log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master (server_errno=1236) 131118
161009 21:42:49 [ERROR] Slave I/O: Got fatal error 1236 from master when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master', Error_code: 1236
++++
解释:
报错主要是:从库读取主库的binlog的packet的大小超出了设定的max_allowed_packet大小,在主库上增加此参数的值。
++++
四、 原因分析:
首先单独操作了表:baby_ord, 此表数据量大大概4百多万的数据条目.
其中在此表上有多个触发器涉及到INSERT\UPDATE\DELETE操作,会触发将相应的数据行插入到baby_delta表中,执行完除了主从延时并没有出现其他的状况
于是过于乐观的认为余下的表没有太大的数据量,除了主从延迟,不会造成其他的问题,索性就全部放在了集中一次发布中修改.
在DBMigrate后监控SQL在主库的执行,主库正常执行完成,从库17和15出现复制崩溃.
查看变更完最后一批表后的binlog大小,其中mysql-bin.007759这一文件达到了将近9G,配置文件中限定产生的binlog文件的最大大小是1G
因为后面一批的表字段添加变更执行是一个事务,同一个事务产生的binlog不会被分配到两个binlog文件中.导致出现上述问题 1和2
事后发现babysitter_campagin 表物理文件有6G大小,其中有几个列的数据类型是text.
但为什么binlog文件会变得这么大呢?超出了限定大小?
因为主库配置的binlog的格式是mixed,由系统根据SQL的类型判断是记录row格式还是stmt格式,但默认是记录stmt格式的,那什么时候会记录
row格式呢?
1.当SQL语句是update或者delete
row格式的缺点就是将每条数据的变化都详细的记录下来,结果就是binlog文件很大,会占用更大的binlog cache.