Using GDB, investigating segmentation fault in MySQL

In previous article, we have covered some errors and issues with using MySQL in “disk full” environment. Where there was no space left on device.(See here: Testing Disk Full Conditions)

Today’s scenario is -> Starting MySQL with GTID/binary log enabled, in 0 space left Linux(CentOS 6.5) environment.

If you hit a bug or problem, general rule for helping community to fix it is to provide as much information as possible. Especially useful is to give gdb output from coredump. To get coredump you can read this wonderful article Hunting-The-Core

Now let’s explore our situation. Because our segfault is detected while starting MySQL, it is not possible to attach PID to GDB and also using strace. Our my.cnf file:

[mysqld] 
log_bin = /opt/mysql/datadir/mysql-bin 
log_bin_index = /opt/mysql/datadir/mysql-bin 
sync_binlog = 1 
binlog_format = row 
gtid-mode = on 
log_slave_updates = 1 
enforce-gtid-consistency = true
sql_mode=NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES core-file 
[mysqld_safe]
core_file_size=unlimited 

Starting MySQL:

[root@localhost ~]# /opt/mysql/bin/mysqld_safe --defaults-file=/opt/mysql/my.cnf --user=mysql --datadir=/opt/mysql/datadir --socket=/opt/mysql/datadir/mysqld-new.sock --pid-file=/home/error_log_dir/mysqld-new.pid --port=3307 --log-error=/home/error_log_dir/error.err & 
[1] 2849 
[root@localhost ~]# 150427 06:31:42 mysqld_safe Logging to '/home/error_log_dir/error.err'. 150427 06:31:42 mysqld_safe Starting mysqld daemon with databases from /opt/mysql/datadir /opt/mysql/bin/mysqld_safe: line 166: 3110 Segmentation fault (core dumped) nohup /opt/mysql/bin/mysqld
--defaults-file=/opt/mysql/my.cnf 
--basedir=/opt/mysql    
--datadir=/opt/mysql/datadir 
--plugin-dir=/opt/mysql/lib/plugin --user=mysql     
--log-error=/home/error_log_dir/error.err 
--pid-file=/home/error_log_dir/mysqld-new.pid 
--socket=/opt/mysql/datadir/mysqld-new.sock 
--port=3307 < /dev/null >> /home/error_log_dir/error.err 2>&1 
150427 06:32:07 mysqld_safe mysqld from pid file /home/error_log_dir/mysqld-new.pid ended 

3110 Segmentation fault (core dumped) -> We have core dump. Using gdb with coredump:

[root@localhost coredumps]# gdb /opt/mysql/bin/mysqld core.3110 
BFD: Warning: /home/coredumps/core.3110 is truncated: expected core file size >= 803807232, found: 697573376. 
[New Thread 3110] 
[New Thread 3111] 
Cannot access memory at address 0x7f5ec00ff168 
Cannot access memory at address 0x7f5ec00ff168 
Cannot access memory at address 0x7f5ec00ff168 
Reading symbols from /lib64/ld-linux-x86-64.so.2...
Reading symbols from /usr/lib/debug/lib64/ld-2.12.so.debug...done. done. 
Loaded symbols for /lib64/ld-linux-x86-64.so.2 Failed to read a valid object file image from memory. 
Core was generated by `/opt/mysql/bin/mysqld --defaults-file=/opt/mysql/my.cnf --basedir=/opt/mysql --'. Program terminated with signal 11, Segmentation fault. #0 0x00007f5ebfccd8ac in ?? () 

(gdb) bt #0 0x00007f5ebfccd8ac in ?? () Cannot access memory at address 0x7fffb0aa89b8 

(gdb) bt full #0 0x00007f5ebfccd8ac in ?? () No symbol table info available. Cannot access memory at address 0x7fffb0aa89b8 

Such information is not sufficient further analysis, that’s why you should try to run MySQL start command with-in GDB as follows:

[root@localhost error_log_dir]# gdb /opt/mysql/bin/mysqld 
(gdb) run --defaults-file=/home/error_log_dir/my.cnf --basedir=/opt/mysql --datadir=/opt/mysql/datadir --plugin-dir=/opt/mysql/lib/plugin --user=mysql --log-error=/home/error_log_dir/error.err --pid-file=/home/error_log_dir/mysqld-new.pid --socket=/opt/mysql/datadir/mysqld-new.sock --port=3307 . . 
Program received signal SIGSEGV, Segmentation fault. 0x0000000000000000 in ?? () . . 

(gdb) bt 
    #0 0x0000000000000000 in ?? () 
    #1 0x0000000000ae6242 in my_printf_warning (format=0x1026f08 "Disk is full writing '%s' (Errcode: %d - %s). Waiting for someone to free space...") at /root/mysql-5.6.24/mysys/my_error.c:260 #2 0x0000000000ac9052 in wait_for_free_space (filename=0x1fe7ee0 "/opt/mysql/datadir/mysql-bin.~rec~", errors=0) at /root/mysql-5.6.24/mysys/errors.c:115 
#3 0x0000000000af1ac7 in my_write (Filedes=19, Buffer=0x1964d00 "/opt/mysql/datadir/mysql-bin.000003n", Count=36, MyFlags=52) at /root/mysql-5.6.24/mysys/my_write.c:89 
#4 0x0000000000acd5ae in inline_mysql_file_write (src_file=0x1027708 "/root/mysql-5.6.24/mysys/mf_iocache.c", src_line=1788, file=19, buffer=0x1964d00 "/opt/mysql/datadir/mysql-bin.000003n", count=36, flags=52) at /root/mysql-5.6.24/include/mysql/psi/mysql_file.h:1141 
#5 0x0000000000ad078c in my_b_flush_io_cache (info=0x183c1a8, need_append_buffer_lock=0) at /root/mysql-5.6.24/mysys/mf_iocache.c:1787 
#6 0x0000000000a7132b in MYSQL_BIN_LOG::sync_purge_index_file (this=0x183b400) at /root/mysql-5.6.24/sql/binlog.cc:4420 
#7 0x0000000000a6e206 in MYSQL_BIN_LOG::open_binlog (this=0x183b400, log_name=0x190d130 "/opt/mysql/datadir/mysql-bin", new_name=0x0, io_cache_type_arg=WRITE_CACHE, max_size_arg=1073741824, null_created_arg=false, need_lock_index=true, need_sid_lock=true, extra_description_event=0x0) at /root/mysql-5.6.24/sql/binlog.cc:3146 
#8 0x000000000063ad8e in init_server_components () at /root/mysql-5.6.24/sql/mysqld.cc:5012 
#9 0x000000000063b6e7 in mysqld_main (argc=19, argv=0x186de68) at /root/mysql-5.6.24/sql/mysqld.cc:5455 
#10 0x000000000062fc74 in main (argc=10, argv=0x7fffffffe3d8) at /root/mysql-5.6.24/sql/main.cc:25 ###################### 

(gdb) bt full 
#0 0x0000000000000000 in ?? () No symbol table info available. 
#1 0x0000000000ae6242 in my_printf_warning (format=0x1026f08 "Disk is full writing '%s' (Errcode: %d - %s). Waiting for someone to free space...") at /root/mysql-5.6.24/mysys/my_error.c:260 args = {{gp_offset = 32, fp_offset = 48, overflow_arg_area = 0x7fffffffd8a0, reg_save_area = 0x7fffffffd7e0}} wbuff = "Disk is full writing '/opt/mysql/datadir/mysql-bin.~rec~' (Errcode: 28 - No space left on device). Waiting for someone to free space...0033032737737737717700002103413773673771770000340267376367377177000027133224u00000000Zn33636737717700000000000000000000/35!3663771770000C00000000000000f223!36637717700000100000000000000P31!3663771770000LC_"... _db_stack_frame_ = {func = 0x102c53c "my_write", file = 0x102c518 "/root/mysql-5.6.24/mysys/my_write.c", level = 2147483654, prev = 0x7fffffffd9f0} 
#2 0x0000000000ac9052 in wait_for_free_space (filename=0x1fe7ee0 "/opt/mysql/datadir/mysql-bin.~rec~", errors=0) at /root/mysql-5.6.24/mysys/errors.c:115 errbuf = "No space left on device003252425700350000002303240201000000002723240201000000000033137737734000000 ܆01000000003400000006000000 ܆0100000000@3313773773771770000[3462570000000000 ܆010000000000܆0123000000<305020100000000303050201000000" 
#3 0x0000000000af1ac7 in my_write (Filedes=19, Buffer=0x1964d00 "/opt/mysql/datadir/mysql-bin.000003n", Count=36, MyFlags=52) at /root/mysql-5.6.24/mysys/my_write.c:89 writtenbytes = 18446744073709551615 sum_written = 0 errors = 0 initial_count = 36 _db_stack_frame_ = {func = 0x1027c7b "my_b_flush_io_cache", file = 0x1027708 "/root/mysql-5.6.24/mysys/mf_iocache.c", level = 2147483653, prev = 0x7fffffffdb10}  

From know developers should be able to see exact code line, for further examination. For further reading(to see “bt full” full output) refer related BUG report: #76852 It is already verified.

Author: Shahriyar Rzayev

Azerbaijan MySQL User Group leader.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s