MySQL从机持续发生core dump现象

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