1. 系统环境
CentOS release 6.7
percona-server-5.6.21-70.0(源码编译安装)
2. 故障简述
主从复制过程中,从机发生core dump
3. 故障排查
3.1. 保留现场
保留现场,将备库数据迁移到新的实例中,在新的实例中,复制追赶主库的过程中,仍然会发生core dump现象,也就是说有一个可以稳定复现的环境。
3.2. 查看日志
错误日志中记录的core dump信息比较固定,每次sql线程执行到relay log中的位置265796980时,发生core dump,对我们排查问题减少了困难。
3.3. 分析core文件
由于可以稳定复现,直接使用gdb在新的环境追查core dump原因,发生core dump时的堆栈信息如下:
Program receivedsignal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7f4434171700(LWP 13995)]
Field_datetime::unpack(this=0x7f3f28011280, to=0x1701 <Address 0x1701 out of bounds>,from=0x7f3f2800d216 "E\336\266wQ\022", param_data=0,low_byte_first=true) at ……
(gdb) bt
#0 Field_datetime::unpack (this=0x7f3f28011280, to=0x1701<Address 0x1701 out of bounds>, from=0x7f3f2800d216"E\336\266wQ\022", param_data=0, low_byte_first=true) at ……
#1 0x00000000008bf649 in unpack_row(rli=<value optimized out>, table=0x7f3f2800d5c0, colcnt=<valueoptimized out>, row_data=0x7f3f2800d203 "", cols=0x7f3f2800d058,
current_row_end=0x7f3f2800d170,master_reclength=0x7f3f2800d118, row_end=0x7f3f2800d5b4 "") at …..
#2 0x000000000088fa31 in unpack_current_row(this=0x7f3f2800cf00, rli=0x20e85460, overwrite=false) at……
#3 Write_rows_log_event::write_row(this=0x7f3f2800cf00, rli=0x20e85460, overwrite=false) at ……
……
分析源码,可以看到发生core dump的源码如下:
Rows_log_event::do_apply_event
| ptr->m_tabledef.compatible_with(thd,const_cast<Relay_log_info*>(rli),
ptr->table, &conv_table,&m_event_mem_root)
| tmp_table=create_conversion_table(thd, rli, table, mem_root);
| Write_rows_log_event::do_exec_row
| Write_rows_log_event::write_row
| unpack_current_row(…..
| unpack_row(Relay_log_infoconst *rli, TABLE *table,……
| conv_field= conv_table ? conv_table->field[field_ptr -begin_ptr] : NULL;
| f = conv_field ?conv_field : *field_ptr;
|f->unpack(f->ptr,pack_ptr, metadata, TRUE);
| Field_datetime::unpack_int64(to,from, low_byte_first);
指针conv_table->field[6]变成了非法地址,访问conv_table->field[6]->ptr发生了访问越界的情况。猜测是由于bug导致conv_table->field[6]由于内存越界被覆盖或者由于内存释放导致了野指针。
3.4. 定位产生问题的操作
结构体conv_table在函数m_tabledef.compatible_with中分配地址空间,在执行行到relay log中的位置265796980发生core dump。
我们使用gdb工具在relay log的位置为265796980时定位到函数Rows_log_event::do_apply_event。
执行操作,设置条件断点:
(gdb) b Rows_log_event::do_apply_rowif active_mi->rli->future_event_relay_log_pos==265796980
逐步执行操作,观察conv_table->field[6]的变化。发现在与存储引擎交互之后,该变量的值被覆盖了。
Write_rows_log_event::write_row
| unpack_current_row(rli, &m_cols)) coredump 函数
| while ((error= table->file->ha_write_row(table->record[0])))handle模块,与引擎交互
进一步查看,发生覆盖的地方
ha_write_row
| row_insert_for_mysql
| row_ins_step
| row_ins_sec_index_entry_low
……
| ut_malloc_nokey
….
| ptr = malloc(total_bytes);
定位原因为malloc申请到的内存地址与变量conv_table->field[6]的内存地址有重叠的地方。
3.5. 重新review代码
查看变量申请内存的源码
ptr->m_tabledef.compatible_with(thd,const_cast<Relay_log_info*>(rli),ptr->table, &conv_table,&m_event_mem_root))
| tmp_table= create_conversion_table(thd, rli, table, mem_root);
| field_def= (Create_field*) alloc_root(mem_root,sizeof(Create_field));
m_event_mem_root为每个event的内存池,在event执行结束后发生释放,但是conv_table为整个事务的转换表,生命周期要比更长。所以产生了野指针,发生了core dump。
4. 总结
如果一个事务内存在两条或者以上的dml语句,并且主库或者从库的表结构存在不一致,同时设置了SLAVE_TYPE_CONVERSIONS,使主从表结构做兼容。那么就有可能发生core dump的现象。
……
Query_log_event
Row_log_event1 使用m_event_mem_root为conv_table分配空间
Row_log_event2 m_event_mem_root已经释放,conv_table任然在继续使用
……
如上所示,再次访问conv_table时,就可能发生core dump。
5. 修复
官方在版本Percona-Server-5.6.22-71.0修复了此bug,修复详情如下:
https://github.com/percona/percona-server/commit/efc00255d65bc56e9f37e1b3b46603dc4260a8a9