MySQL Bugs: #52546: crash on shutdown of plugin with innodb_use_sys

Bug #52546	crash on shutdown of plugin with innodb_use_sys_malloc=0
Submitted:	2 Apr 2010 5:53	Modified:	4 Aug 2010 19:46
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB Plugin storage engine	Severity:	S1 (Critical)
Version:	5.1.45, 5.5.4-m3	OS:	Any
Assigned to:	Jimmy Yang	CPU Architecture:	Any

Description:
innodb_use_sys_malloc=0 makes the innodb plugin crash during shutdown:

ntdll.dll!RtlCheckForOrphanedCriticalSections()
ntdll.dll!RtlCheckForOrphanedCriticalSections()
ha_innodb_plugin.dll!os_fast_mutex_lock()[os0sync.c:666]
ha_innodb_plugin.dll!ut_free()[ut0mem.c:312]
ha_innodb_plugin.dll!mem_pool_free()[mem0pool.c:272]
ha_innodb_plugin.dll!mem_close()[mem0dbg.c:181]
ha_innodb_plugin.dll!innobase_shutdown_for_mysql()[srv0start.c:2033]
ha_innodb_plugin.dll!innobase_end()[ha_innodb.cc:2289]
mysqld.exe!ha_finalize_handlerton()[handler.cc:395]
mysqld.exe!plugin_deinitialize()[sql_plugin.cc:828]
mysqld.exe!reap_plugins()[sql_plugin.cc:916]
mysqld.exe!plugin_shutdown()[sql_plugin.cc:1544]
mysqld.exe!clean_up()[mysqld.cc:1297]
mysqld.exe!unireg_end()[mysqld.cc:1224]
mysqld.exe!kill_server()[mysqld.cc:1167]
mysqld.exe!handle_shutdown()[mysqld.cc:2981]
mysqld.exe!pthread_start()[my_winthread.c:85]
mysqld.exe!_callthreadstart()[thread.c:293]
mysqld.exe!_threadstart()[thread.c:275]

How to repeat:
start mysqld --ignore-builtin-innodb --plugin-load=innodb=ha_innodb_plugin.dll 
--innodb_file_per_table --innodb_file_format=barracuda --innodb_use_sys_malloc=0

mysqladmin shutdown

ut_free_all_mem had already freed pool->buf and this crash then happens because mem_pool_free tries to free pool->buf (already freed)

Verified just as described, also - with recent mysql-trunk tree from bzr, where plugin is used as a default InnoDB engine:

openxs@ubuntu:/home2/openxs/dbs/trunk$ libexec/mysqld --no-defaults --innodb_use_sys_malloc=0
100402  9:49:26 [Note] Buffered information: Performance schema disabled (reason: start parameters).

100402  9:49:26 [Note] Plugin 'FEDERATED' is disabled.
100402  9:49:26 [Note] Plugin 'ndbcluster' is disabled.
InnoDB: Mutexes and rw_locks use GCC atomic builtins
100402  9:49:27  InnoDB: highest supported file format is Barracuda.
100402  9:49:27 InnoDB Plugin 1.0.6 started; log sequence number 44278
100402  9:49:28 [Note] Event Scheduler: Loaded 0 events
100402  9:49:28 [Note] libexec/mysqld: ready for connections.
Version: '5.5.4-m3-debug'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
100402  9:49:56 [Note] Got signal 15 to shutdown mysqld
100402  9:49:56 [Note] libexec/mysqld: Normal shutdown

100402  9:49:56 [Note] Event Scheduler: Purging the queue. 0 events
100402  9:49:56  InnoDB: Starting shutdown...
safe_mutex: Trying to lock unitialized mutex at os/os0sync.c, line 664
100402  9:49:57 - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=1
max_threads=151
thread_count=0
connection_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 337841 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = (nil) thread_stack 0x30000
libexec/mysqld(my_print_stacktrace+0x26)[0x8781ae1]
libexec/mysqld(handle_segfault+0x2ee)[0x82c884e]
[0xb7730420]
/lib/tls/i686/cmov/libc.so.6(abort+0x101)[0xb7572a01]
libexec/mysqld(safe_mutex_lock+0x4d)[0x878e308]
libexec/mysqld[0x858fa85]
libexec/mysqld[0x85db523]
libexec/mysqld[0x8588a18]
libexec/mysqld[0x8587cd0]
libexec/mysqld[0x85c5bc9]
libexec/mysqld[0x8568bde]
libexec/mysqld(_Z22ha_finalize_handlertonP13st_plugin_int+0x95)[0x8419e35]
libexec/mysqld[0x84eafc1]
libexec/mysqld[0x84eb1ee]
libexec/mysqld(_Z15plugin_shutdownv+0x70)[0x84eb8f2]
libexec/mysqld[0x82ca0bd]
libexec/mysqld(_Z10unireg_endv+0x12)[0x82ca318]
libexec/mysqld[0x82cc952]
libexec/mysqld(kill_server_thread+0x17)[0x82cc971]
/lib/tls/i686/cmov/libpthread.so.0[0xb770e4fb]
/lib/tls/i686/cmov/libc.so.6(clone+0x5e)[0xb761ce5e]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
...

This is a bug in the code that reuses "ut_list_mutex" after it is freed.
The related code fragment is:

innobase_shutdown_for_mysql()
{

   2095         ut_free_all_mem();  <=== ut_list_mutex is freed
   2096         mem_close();      <===  os_fast_mutex_lock(&ut_list_mutex); is called in ut_free() if srv_use_sys_malloc set to 0

}

In ut_free_all_mem(), we free the ut_list_mutex:

ut_free_all_mem()
{
    ...os_fast_mutex_free(&ut_list_mutex);
}

Subsequently, following functions are called mem_close()->mem_pool_free()->ut_free(). In ut_free(), if srv_use_sys_malloc is set, we will call free(ptr) and return directly, if srv_use_sys_malloc is not set, we will try to lock ut_list_mutex again:

ut_free()
{
        if (ptr == NULL) {
                return;
        } else if (UNIV_LIKELY(srv_use_sys_malloc)) { <=====
                free(ptr);  <=== return if srv_use_sys_malloc is set
                return;
        }

        ....
        os_fast_mutex_lock(&ut_list_mutex); <=== Trigger the error
    
        ....
}

Since we try to lock ut_list_mutex again after it is freed, error is reported:

int safe_mutex_lock()
{
  int error;
  if (!mp->file)
  {
    fprintf(stderr,
            "safe_mutex: Trying to lock unitialized mutex at %s, line %d\n",
            file, line);
    fflush(stderr);
    abort();  <===
  }

whole stack:
#0  0x00aba422 in __kernel_vsyscall ()
#1  0x0042c4d1 in raise () from /lib/tls/i686/cmov/libc.so.6
#2  0x0042f932 in abort () from /lib/tls/i686/cmov/libc.so.6
#3  0x08579e4f in safe_mutex_lock (mp=0x8833560, try_lock=0 '\000', 
    file=0x869edb9 "os/os0sync.c", line=664) at thr_mutex.c:106
#4  0x0844e868 in os_fast_mutex_lock (fast_mutex=0x8833560)
    at os/os0sync.c:664
#5  0x08499e3c in ut_free (ptr=0xb759b018) at ut/ut0mem.c:313
#6  0x0844767a in mem_pool_free (pool=0x887a2d8) at mem/mem0pool.c:276
#7  0x084468e8 in mem_close () at mem/mem0dbg.c:187
#8  0x08484911 in innobase_shutdown_for_mysql ()

Fix is being evaluated.

Thanks
Jimmy

with UNIV_DEBUG and UNIV_SYNC_DEBUG we have a crash a bit earlier
because of a different reason, let's consider it under the same bug.

100513  7:45:17  InnoDB: Assertion failure in thread 1092602176 in file /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/sync/sync0sync.c line 413
InnoDB: Failing assertion: mutex->magic_n == MUTEX_MAGIC_N
100513  7:45:17 - mysqld got signal 6 ;

dscczz02:/spare2/mizioumt/ctc/data/c55/core.18231

extracting stack backtrace for core.18231...
 Thread 1 (process 18466):
 #0  0x0000003c1ae0b9b2 in pthread_kill () from /lib64/libpthread.so.0
 #1  0x00000000009f4f6f in my_write_core (sig=6)
     at /spare2/mizioumt/ctc/mysql_src_c55/mysys/stacktrace.c:326
 #2  0x0000000000532455 in handle_segfault (sig=6)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/mysqld.cc:2786
 #3  <signal handler called>
 #4  0x0000003c1a230265 in raise () from /lib64/libc.so.6
 #5  0x0000003c1a231d10 in abort () from /lib64/libc.so.6
 #6  0x0000000000887760 in mutex_validate (mutex=0x10793868)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/sync/sync0sync.c:413
 #7  0x0000000000886b85 in mutex_enter_func (mutex=0x10793868,
     file_name=0xb2f4a0 "/spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/mem/mem0pool.c", line=575)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/include/sync0sync.ic:206
 #8  0x0000000000886cf6 in pfs_mutex_enter_func (mutex=0x10793868,
     file_name=0xb2f4a0 "/spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/mem/mem0pool.c", line=575)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/include/sync0sync.ic:250
 #9  0x000000000092ec97 in mem_area_free (ptr=0x2aaaabe1b048, pool=0x10793850)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/mem/mem0pool.c:575
 #10 0x000000000092d901 in mem_heap_block_free (heap=0x2aaaabe1b048,
     block=0x2aaaabe1b048)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/mem/mem0mem.c:511
 #11 0x000000000092b17d in mem_heap_free_func (heap=0x2aaaabe1b048,
     file_name=0xb0a428 "/spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/srv/srv0srv.c", line=1044)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/include/mem0mem.ic:504
 #12 0x000000000092b2bd in mem_free_func (ptr=0x2aaaabe1b0d0,
     file_name=0xb0a428 "/spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/srv/srv0srv.c", line=1044)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/include/mem0mem.ic:571
 #13 0x000000000087bda8 in srv_free ()
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/srv/srv0srv.c:1044
 #14 0x0000000000882b3f in innobase_shutdown_for_mysql ()
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/srv/srv0start.c:2084
 #15 0x00000000008493cb in innobase_end (hton=0x1075fd50, type=HA_PANIC_CLOSE)
     at /spare2/mizioumt/ctc/mysql_src_c55/storage/innobase/handler/ha_innodb.cc:2472
 #16 0x00000000006f613e in ha_finalize_handlerton (plugin=0x107907f0)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/handler.cc:420
 #17 0x00000000005bdef3 in plugin_deinitialize (plugin=0x107907f0,
     ref_check=true) at /spare2/mizioumt/ctc/mysql_src_c55/sql/sql_plugin.cc:866
 #18 0x00000000005be3a6 in reap_plugins ()
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/sql_plugin.cc:954
 #19 0x00000000005c07b1 in plugin_shutdown ()
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/sql_plugin.cc:1641
 #20 0x00000000005310bb in clean_up (print_message=true)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/mysqld.cc:1505
 #21 0x00000000005318c2 in unireg_end ()
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/mysqld.cc:1421
 #22 0x0000000000534bb2 in kill_server (sig_ptr=0x0)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/mysqld.cc:1344
 #23 0x0000000000534bd7 in kill_server_thread (arg=0x4117a118)
     at /spare2/mizioumt/ctc/mysql_src_c55/sql/mysqld.cc:1372
 #24 0x0000003c1ae064a7 in start_thread () from /lib64/libpthread.so.0
 #25 0x0000003c1a2d3c2d in clone () from /lib64/libc.so.6

The problem is here I think:

        /* 3. Free all InnoDB's own mutexes and the os_fast_mutexes inside
        them */
        os_aio_free();
        sync_close();
        srv_free();
        fil_close();

in innobase_shutdown_for_mysql()

the mutex that we are trying to acquire in srv_free() is I think 
freed in sync_close().

Michael, your observation is correct. In this case, we will check whether server is in shutdown stage and do not use mutex during memory free operation. We do not switch sync_close() and srv_free() functions in this case, since srv_free() function and its calling functions had the assumption that mutex are freed.

Pushed into 5.5.5-m3 (revid:alik@sun.com-20100615080459-smuswd9ooeywcxuc) (version source revid:marko.makela@oracle.com-20100518130658-rd00ql7h02ooakh1) (merge vers: 5.1.48) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100615080558-cw01bzdqr1bdmmec) (version source revid:marko.makela@oracle.com-20100518130658-rd00ql7h02ooakh1) (pib:16)

Added to 5.5.5 change log:

The server could crash during shutdown, if started with the option --innodb_use_sys_malloc=0.