Bug #20541 MySQL Server segfaults when issuing 'mysqladmin refresh'
Submitted: 19 Jun 2006 16:51 Modified: 20 Jul 2006 19:10
Reporter: Sander Smeenk Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:5.0.22 OS:Linux (Debian GNU/Linux kernel 2.6.15.1)
Assigned to: CPU Architecture:Any

[19 Jun 2006 16:51] Sander Smeenk
Description:
I'm running MySQL 5.0.22, on a Dual Opteron 250 system (64bit) and
discovered i have a reproducable mysql crash when calling 'mysqladmin
refresh'.

There is but one weird aspect to this story. I'm running exactly the
same version of MySQL on exactly the same hardware and on the other
system it doesn't crash when refreshed...
(Both have dual Opteron 250, 2GB ram, 4x32gb scsi u320 disks)

The crashable server is in a replication setup with the non-crashable
server. The crashable server is configured as slave for the
non-crashable server.

This is a gdb trace from the moment i made mysqld crash by issuing a
refresh. It looks to me like it has to do with the replication...

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 1141422432 (LWP 6865)]
0x00000000008823e9 in reinit_io_cache (info=0xc83560, type=READ_CACHE, seek_offset=0,
    use_async_io=<value optimized out>, clear_cache=0 '\0') at mf_iocache.c:326
326       if (! clear_cache &&
Current language:  auto; currently c
(gdb) bt full
#0  0x00000000008823e9 in reinit_io_cache (info=0xc83560, type=READ_CACHE, seek_offset=0,
    use_async_io=<value optimized out>, clear_cache=0 '\0') at mf_iocache.c:326
        _db_func_ = 0x4408a4d0 "`�\bD"
        _db_file_ = 0x3274408a4e4 <Address 0x3274408a4e4 out of bounds>
        _db_level_ = 0
        _db_framep_ = (char **) 0xcbc820
        __PRETTY_FUNCTION__ = "reinit_io_cache"
#1  0x00000000005fa3cc in MYSQL_LOG::find_log_pos (this=0xc83260, linfo=0x4408a560,
    log_name=0x0, need_lock=false) at log.cc:819
        fname = <value optimized out>
        log_name_len = 0
        _db_func_ = 0x87b742 "H\203�\211�]A\\A]A^A_�\2138�205\201"
        _db_file_ = 0x4c44408a520 <Address 0x4c44408a520 out of bounds>
        error = <value optimized out>
        _db_level_ = 0
        _db_framep_ = (char **) 0x4408a534
        __PRETTY_FUNCTION__ = "int MYSQL_LOG::find_log_pos(LOG_INFO*, const char*, bool)"
#2  0x00000000005fda9d in MYSQL_LOG::purge_logs_before_date (this=0xc83260,
    purge_time=1150281571) at log.cc:1229
        _db_func_ = 0x4408a898 ""
        _db_file_ = 0x1ad1 <Address 0x1ad1 out of bounds>
        error = <value optimized out>
        log_info = {
  log_file_name = "إ\bD\000\000\000\000�_\000\000\000\000\000�\bD", '\0' <repeats 16 times>, "9\0
00\000\000\200\006���*\000\000�bD\000\000\000\000��000\000\000\000\000�bD\000\000\000\000�bD\000\
000\000\000�bD\032\005\000\000��\bD\000\000\000\000��\bD\000\000\000\000\002\000\000\000\000\000\
000\000`2�, '\0' <repeats 13 times>, "\234�\bD\000\000\000\000\210�\bD\000\000\000\000\220�\bD\00
0\000\000\000I�\000\000\000\000\000\200�\bD\000\000\000\000��\bD\000\000\000\000��\bD\000\000\000
\000�_", '\0' <repeats 13 times>, "\001", '\0' <repeats 14 times>, "\001"...,
  index_file_offset = 0, index_file_start_offset = 23074872, pos = 16, fatal = false, lock = {
    global = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 2,
        __spins = 0}, __size = '\0' <repeats 16 times>, "\002", '\0' <repeats 22 times>,
      __align = 0}, mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0,
        __kind = 3, __spins = 0},
      __size = '\0' <repeats 16 times>, "\003", '\0' <repeats 22 times>, __align = 0},
    file = 0x8c9994 "sql_class.h", line = 161, count = 0, thread = 0}}
        stat_area = {st_dev = 11871680, st_ino = 0, st_nlink = 23074944, st_mode = 0,
  st_uid = 0, st_gid = 0, pad0 = 0, st_rdev = 23075880, st_size = 1141418068,
  st_blksize = 6980750, st_blocks = 6675520596024, st_atim = {tv_sec = 5818117,
    tv_nsec = 245954553928}, st_mtim = {tv_sec = 0, tv_nsec = 23074816}, st_ctim = {
    tv_sec = 23074840, tv_nsec = 1141418136}, __unused = {1141418148, 1141418128, 5668620}}
        _db_level_ = 0
        _db_framep_ = (char **) 0xc7e0e0
#3  0x00000000005fef1e in MYSQL_LOG::rotate_and_purge (this=0xc83260, flags=2) at log.cc:1772
        purge_time = 0
#4  0x000000000058cdb0 in reload_acl_and_cache (thd=0x1601800, options=46, tables=0x0,
    write_to_binlog=0x4408aeff) at sql_parse.cc:6602
        tmp_thd = (class THD *) 0x1601800
        __PRETTY_FUNCTION__ = "bool reload_acl_and_cache(THD*, ulong, TABLE_LIST*, bool*)"
#5  0x0000000000598845 in dispatch_command (command=COM_REFRESH, thd=0x1601800,
    packet=0x1603d31 ".", packet_length=<value optimized out>) at sql_parse.cc:1934
        not_used = false
        options = 46
#6  0x00000000005994a2 in do_command (thd=0x1601800) at sql_parse.cc:1522
        packet = 0x1603d30 "\a."
        old_timeout = 30
        packet_length = 2
        net = (NET *) 0x1602600
        command = COM_REFRESH
        _db_func_ = 0x8842cc "H\205�\211�(\211h\fD\211h\bH\213\003H\211\002I\211T$\020H\211\023H\203�b[]A\\A]��\020"
        _db_file_ = 0x1602600 " �Z\001"
        _db_level_ = 0
        _db_framep_ = (char **) 0x0
#7  0x0000000000599c02 in handle_one_connection (arg=0x1601800) at sql_parse.cc:1165
        error = <value optimized out>
        net = (NET *) 0x1602600
        sctx = (Security_context *) 0x1603298
        thd = (class THD *) 0x1601800
        set = {__val = {0 <repeats 16 times>}}
#8  0x00002aaaaaff5b1c in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#9  0x00002aaaab8b19c2 in clone () from /lib/libc.so.6
No symbol table info available.
#10 0x0000000000000000 in ?? ()
No symbol table info available.

How to repeat:
Issue 'mysqladmin refresh' on my server.
As i wrote above, it only seems to happen on that specific server.

Suggested fix:
I don't know of a fix. The mysqld_safe wrapper script incorporated in Debian (and possibly others) restarts the server and all looks fine, but this should just not happen.
[23 Jun 2006 9:50] Valeriy Kravchuk
Thank you for a problem report. Please, send your my.cnf file content. Does this happen on each and every 'mysqladmin refresh'? Do you have anything unusual in the error log?
[23 Jun 2006 10:04] Sander Smeenk
[23 Jun 11:50] Valeriy Kravchuk
> Thank you for a problem report. Please, send your my.cnf file content.

Okay! I will post it with the bugreport.

> Does this happen on each and every 'mysqladmin refresh'?

Yes. Each and every time i type 'mysqladmin refresh' it segfaults the server. So if you want more gdb traces, i can reproduce the problem.

> Do you have anything unusual in the error log?

Nothing at all, actually. Except the segfault error which is:

mysqld[8199]: mysqld got signal 11;
mysqld[8199]: This could be because you hit a bug. It is also possible that this binary
mysqld[8199]: or one of the libraries it was linked against is corrupt, improperly built,
mysqld[8199]: or misconfigured. This error can also be caused by malfunctioning hardware.
mysqld[8199]: We will try our best to scrape up some info that will hopefully help diagnose
mysqld[8199]: the problem, but since we have already crashed, something is definitely wrong
mysqld[8199]: and this may fail.
mysqld[8199]: 
mysqld[8199]: key_buffer_size=33554432
mysqld[8199]: read_buffer_size=131072
mysqld[8199]: max_used_connections=1 
mysqld[8199]: max_connections=100
mysqld[8199]: threads_connected=1
mysqld[8199]: It is possible that mysqld could use up to 
mysqld[8199]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 250367 K
mysqld[8199]: bytes of memory
mysqld[8199]: Hope that's ok; if not, decrease some variables in the equation.
mysqld[8199]: 
mysqld_safe[8227]: Number of processes running now: 0
mysqld_safe[8229]: restarted
mysqld[8232]: 060623  8:30:46  InnoDB: Started; log sequence number 0 43655
mysqld[8232]: 060623  8:30:46 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=oranje-relay
mysqld[8232]: 060623  8:30:46 [Note] /usr/sbin/mysqld: ready for connections. 
mysqld[8232]: Version: '5.0.22-Debian_2-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Debian Etch distribution
mysqld[8232]: 060623  8:30:46 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000467' at position 101558505, relay log './oranje-relay-bin.002496' position: 235
mysqld[8232]: 060623  8:30:46 [Note] Slave I/O thread: connected to master 'vgl_repl@zwart.hostname.tld:3306',  replication started in log 'mysql-bin.000467' at position 101558505
[20 Jul 2006 19:10] Valeriy Kravchuk
As you have expire-logs-days = 1, it is, almost surely, a duplicate of bug #17733. Refresh means "Flush all tables and close and open log files."