Hi Aleksey,
Does it happen every time, or does it depend on the workload / number of connections during the shutdown?
At the first glance it looks like the upstream bug https://bugs.launchpad.net/codership-mysql/+bug/1099742 , but i'm not 100% sure since their error log seems much shorter (or they didn't quote the whole thing), and we don't have anything else to compare. Would you be able to run strace and/or gdb bt so we could see if it stops at the same place as in the other bug?
Thanks
This happens 100% of the time. Server is doing nothing. Yes, I can try to get gdb tomorrow.
Forgot to mention, that this is definitely related to WSREP/Galera: same server, same configs with commented out wsrep_XXX options in my.cnf stops and restarts w/o problems.
I've set up a 5.5.28a node on CentOS 5.8 and shutdown works for me, but the sequence of events in the log is somewhat different, so apparently there might be some race conditions involved.
Lets wait for gdb results before digging further.
If gdb doesn't show that it's the same problem as in the Codership bug report, I'll ask you to provide your cnf files and will try to reproduce with them.
GDB stacktraces:
[root@devdb02 ~]# ps -ef | grep mysql
root 17374 1 0 01:50 pts/0 00:00:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --pid-file=/var/lib/mysql/devdb02.corp.wepay-inc.com.pid
mysql 18257 17374 0 01:51 pts/0 00:00:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/lib/mysql/devdb02.corp.wepay-inc.com.pid --socket=/var/lib/mysql/mysql.sock --port=53306 --wsrep_start_position=34b486ae-6f0c-11e2-0800-5cdefb8ea919:277450
root 18287 16997 0 01:51 pts/0 00:00:00 /bin/sh /etc/init.d/mysql stop
root 19160 17091 0 01:58 pts/1 00:00:00 grep mysql
[root@devdb02 ~]# gdb --batch -ex "thr apply all bt" -p $(pidof mysqld) /usr/bin/mysqld
/usr/bin/mysqld: No such file or directory.
[Thread debugging using libthread_db enabled]
[New Thread 0x41815940 (LWP 18298)]
[New Thread 0x41bcb940 (LWP 18283)]
[New Thread 0x4da26940 (LWP 18282)]
[New Thread 0x4d025940 (LWP 18281)]
[New Thread 0x4c624940 (LWP 18280)]
[New Thread 0x4bc23940 (LWP 18279)]
[New Thread 0x4b222940 (LWP 18278)]
[New Thread 0x4a821940 (LWP 18277)]
[New Thread 0x49e20940 (LWP 18276)]
[New Thread 0x4941f940 (LWP 18274)]
[New Thread 0x48a1e940 (LWP 18273)]
[New Thread 0x4801d940 (LWP 18272)]
[New Thread 0x4761c940 (LWP 18271)]
[New Thread 0x46c1b940 (LWP 18270)]
[New Thread 0x4621a940 (LWP 18269)]
[New Thread 0x45819940 (LWP 18268)]
[New Thread 0x44e18940 (LWP 18267)]
[New Thread 0x44417940 (LWP 18266)]
[New Thread 0x43a16940 (LWP 18265)]
[New Thread 0x43015940 (LWP 18264)]
[New Thread 0x41713940 (LWP 18262)]
[New Thread 0x40c91940 (LWP 18259)]
warning: no loadable sections found in added symbol-file system-supplied DSO at 0x7fff2f7fd000
0x0000003b8a40af59 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
Thread 23 (Thread 0x40c91940 (LWP 18259)):
#0 0x0000003b8a40af59 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00002aaab355a085 in wait (arg=0x12d6c4e0) at galerautils/src/gu_lock.hpp:56
#2 galera::ServiceThd::thd_func (arg=0x12d6c4e0) at galera/src/galera_service_thd.cpp:25
#3 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#4 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 22 (Thread 0x41713940 (LWP 18262)):
#0 0x0000003b8a40af59 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000058f8d7 in wsrep_rollback_process(THD*) ()
#2 0x000000000050af2c in start_wsrep_THD ()
#3 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#4 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 21 (Thread 0x43015940 (LWP 18264)):
#0 0x0000003b8a40b1c0 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000882baf in my_service_thread_sleep ()
#2 0x000000000087b0ab in ma_checkpoint_background ()
#3 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#4 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 20 (Thread 0x43a16940 (LWP 18265)):
#0 0x0000000000a580c4 in __io_getevents_0_4 ()
#1 0x0000000000a2e904 in os_aio_linux_handle ()
#2 0x00000000009e2953 in fil_aio_wait ()
#3 0x0000000000965f18 in io_handler_thread ()
#4 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#5 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 19 (Thread 0x44417940 (LWP 18266)):
#0 0x0000000000a580c4 in __io_getevents_0_4 ()
#1 0x0000000000a2e904 in os_aio_linux_handle ()
#2 0x00000000009e2953 in fil_aio_wait ()
#3 0x0000000000965f18 in io_handler_thread ()
#4 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#5 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 18 (Thread 0x44e18940 (LWP 18267)):
#0 0x0000000000a580c4 in __io_getevents_0_4 ()
#1 0x0000000000a2e904 in os_aio_linux_handle ()
#2 0x00000000009e2953 in fil_aio_wait ()
#3 0x0000000000965f18 in io_handler_thread ()
#4 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#5 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 17 (Thread 0x45819940 (LWP 18268)):
#0 0x0000000000a580c4 in __io_getevents_0_4 ()
#1 0x0000000000a2e904 in os_aio_linux_handle ()
#2 0x00000000009e2953 in fil_aio_wait ()
#3 0x0000000000965f18 in io_handler_thread ()
#4 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#5 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 16 (Thread 0x4621a940 (LWP 18269)):
#0 0x0000000000a580c4 in __io_getevents_0_4 ()
#1 0x0000000000a2e904 in os_aio_linux_handle ()
#2 0x00000000009e2953 in fil_aio_wait ()
#3 0x0000000000965f18 in io_handler_thread ()
#4 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#5 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 15 (Thread 0x46c1b940 (LWP 18270)):
--Type <return> to continue, or q <return> to quit--
#0 0x0000000000a580c4 in __io_getevents_0_4 ()
#1 0x0000000000a2e904 in os_aio_linux_handle ()
#2 0x00000000009e2953 in fil_aio_wait ()
#3 0x0000000000965f18 in io_handler_thread ()
#4 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#5 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 14 (Thread 0x4761c940 (LWP 18271)):
#0 0x0000000000a580c4 in __io_getevents_0_4 ()
#1 0x0000000000a2e904 in os_aio_linux_handle ()
#2 0x00000000009e2953 in fil_aio_wait ()
#3 0x0000000000965f18 in io_handler_thread ()
#4 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#5 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 13 (Thread 0x4801d940 (LWP 18272)):
#0 0x0000000000a580c4 in __io_getevents_0_4 ()
#1 0x0000000000a2e904 in os_aio_linux_handle ()
#2 0x00000000009e2953 in fil_aio_wait ()
#3 0x0000000000965f18 in io_handler_thread ()
#4 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#5 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 12 (Thread 0x48a1e940 (LWP 18273)):
#0 0x0000000000a580c4 in __io_getevents_0_4 ()
#1 0x0000000000a2e904 in os_aio_linux_handle ()
#2 0x00000000009e2953 in fil_aio_wait ()
#3 0x0000000000965f18 in io_handler_thread ()
#4 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#5 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 11 (Thread 0x4941f940 (LWP 18274)):
#0 0x0000000000a580c4 in __io_getevents_0_4 ()
#1 0x0000000000a2e904 in os_aio_linux_handle ()
#2 0x00000000009e2953 in fil_aio_wait ()
#3 0x0000000000965f18 in io_handler_thread ()
#4 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#5 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 10 (Thread 0x49e20940 (LWP 18276)):
#0 0x0000003b8a40b1c0 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000a30893 in os_event_wait_time_low ()
#2 0x0000000000962bd0 in srv_lock_timeout_thread ()
#3 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#4 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 9 (Thread 0x4a821940 (LWP 18277)):
#0 0x0000003b8a40b1c0 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000a30893 in os_event_wait_time_low ()
#2 0x0000000000963267 in srv_error_monitor_thread ()
#3 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#4 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 8 (Thread 0x4b222940 (LWP 18278)):
#0 0x0000003b8a40b1c0 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000a30893 in os_event_wait_time_low ()
#2 0x0000000000962613 in srv_monitor_thread ()
#3 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#4 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 7 (Thread 0x4bc23940 (LWP 18279)):
#0 0x0000003b8a40b1c0 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000a30893 in os_event_wait_time_low ()
#2 0x000000000095f433 in srv_LRU_dump_restore_thread ()
--Type <return> to continue, or q <return> to quit--
#3 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#4 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 6 (Thread 0x4c624940 (LWP 18280)):
#0 0x0000003b8a40af59 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000a309d1 in os_event_wait_low ()
#2 0x0000000000963e66 in srv_master_thread ()
#3 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#4 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 5 (Thread 0x4d025940 (LWP 18281)):
#0 0x0000003b8a40af59 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000a309d1 in os_event_wait_low ()
#2 0x0000000000963816 in srv_purge_thread ()
#3 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#4 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 4 (Thread 0x4da26940 (LWP 18282)):
#0 0x0000003b8a40b1c0 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000006b8cbf in timer_thread(void*) ()
#2 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#3 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 3 (Thread 0x41bcb940 (LWP 18283)):
#0 0x0000003b8a40e908 in do_sigwait () from /lib64/libpthread.so.0
#1 0x0000003b8a40e9ad in sigwait () from /lib64/libpthread.so.0
#2 0x0000000000507fd3 in signal_hand ()
#3 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#4 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 2 (Thread 0x41815940 (LWP 18298)):
#0 0x0000003b8a40af59 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000508cdf in wsrep_wait_appliers_close(THD*) ()
#2 0x000000000069149b in wsrep_stop_replication(THD*) ()
#3 0x000000000050e017 in kill_server ()
#4 0x000000000050e85e in kill_server_thread ()
#5 0x0000003b8a40677d in start_thread () from /lib64/libpthread.so.0
#6 0x0000003b89cd3c1d in clone () from /lib64/libc.so.6
Thread 1 (Thread 0x2b566fee76a0 (LWP 18257)):
#0 0x0000003b8a40af59 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000000510cff in mysqld_main(int, char**) ()
#2 0x0000003b89c1d994 in __libc_start_main () from /lib64/libc.so.6
#3 0x00000000005034d9 in _start ()
[root@devdb02 ~]#
[root@devdb02 ~]#
So it looks similar to the upstream bug indeed. However, it is MariaDB specifc too: I actually tried the stock MySQL 5.5.28a with Galera patches and the problem went away. In the upstream bug the issue is 100% reproducible if one sets wsrep_on to false before shutdown. I believe this is what is happening here as well - somehow wsrep_on is set to false before the wsrep shutdown process starts. It smells like some race condition in the shutdown process with either clearing this flag directly or clearing the whole global_system_variables structure.
Hi Aleksey,
Thank you.
Assigning to Seppo to check why the behavior is specific to MariaDB-Galera. I will also add a comment to the Codership bug report.
Actually, the stack looks somewhat different, in our case it's waiting in
#1 0x0000000000508cdf in wsrep_wait_appliers_close(THD*) ()
#2 0x000000000069149b in wsrep_stop_replication(THD*) ()
while in the LP bug it's in
#1 0x000000000051ee84 in inline_mysql_cond_wait (sig_ptr=0x0) at /builddir/build/BUILD/mysql-5.5.28/mysql-5.5.28/include/mysql/psi/mysql_thread.h:980
#2 close_connections (sig_ptr=0x0) at /builddir/build/BUILD/mysql-5.5.28/mysql-5.5.28/sql/mysqld.cc:1241
I'll leave it to Seppo to decide whether it's a duplicate or a separate problem.
output with wsrep_debug = 1
130212 3:42:48 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 1745947)
130212 3:42:48 [Note] WSREP: New cluster view: global state: 91e773e6-725d-11e2-0800-1d679f8c5252:1745947, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 2
130212 3:42:48 [Note] WSREP: Setting wsrep_ready to 0
130212 3:42:48 [Note] WSREP: RECV thread exiting 0: Success
130212 3:42:48 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
130212 3:42:48 [Note] WSREP: recv_thread() joined.
130212 3:42:48 [Note] WSREP: Closing slave action queue.
130212 3:42:48 [Note] WSREP: New cluster view: global state: 91e773e6-725d-11e2-0800-1d679f8c5252:1745947, view# -1: non-Primary, number of nodes: 0, my index: -1, protocol version 2
130212 3:42:48 [Note] WSREP: Setting wsrep_ready to 0
130212 3:42:48 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
130212 3:42:48 [Note] WSREP: applier thread exiting (code:0)
130212 3:42:48 [Note] WSREP: closing applier 5
130212 3:42:48 [Note] WSREP: applier thread exiting (code:5)
130212 3:42:48 [Note] WSREP: closing applier 2
130212 3:42:48 [Note] WSREP: applier thread exiting (code:5)
130212 3:42:48 [Note] WSREP: closing applier 4
130212 3:42:48 [Note] WSREP: applier thread exiting (code:5)
130212 3:42:48 [Note] WSREP: closing applier 3
130212 3:42:50 [Note] WSREP: waiting for client connections to close: 5
130212 3:42:50 [Note] WSREP: Informing thread 5 that it's time to die
130212 3:42:50 [Note] WSREP: Informing thread 4 that it's time to die
130212 3:42:50 [Note] WSREP: Informing thread 3 that it's time to die
130212 3:42:50 [Note] WSREP: Informing thread 2 that it's time to die
130212 3:42:50 [Note] WSREP: Informing thread 1 that it's time to die
130212 3:42:51 [Note] WSREP: Before Lock_thread_count
I think I figured it out. The problem is in the "thread_handling=pool-of-threads" setting. If I remove it then the shutdown goes just fine. With the "thread_handling=pool-of-threads", the unlink_thd() is not called (probably because one_thread_per_connection_scheduler() is not called.
So yes, it was MariaDB specific at the end 
Thank you, Aleksey.
It is totally reproducible with thread pool indeed.
Reproducible on current maria-5.5-galera tree as well (revno 3378).
To reproduce, it's enough to start server with
--wsrep_cluster_address=gcomm:// --wsrep_provider=<path_to_the_library>/libgalera_smm.so --thread-handling=pool-of-threads
wait till it starts, then try to shut it down.
Seppo,
Wlad can consult from the thread pool side, please contact him if needed.
Committed a simple fix, which enables graceful shutdown of wsrep replicator when thread pool scheduler is being used.
We have conflicting work in upstream, which deals with dynamic slave thread management. This fix is therefore quite temporary and will be re-factored latest by when wsrep API #24 will be supported.
Fix was committed in revision: http://bazaar.launchpad.net/~maria-captains/maria/maria-5.5-galera/revision/3379