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.   修复