Percona Server moved to https://jira.percona.com/projects/PS

Intermittently stalled or crashing shutdown if it's issued immediately after HandlerSocket startup

Bug #1617198 reported by Laurynas Biveinis on 2016-08-26

This bug affects 1 person

	Status	Importance	Assigned to	Milestone
Percona Server moved to https://jira.percona.com/projects/PS	Status tracked in 5.7
5.5	Invalid	Undecided	Unassigned
5.6	Fix Released	High	Laurynas Biveinis	Percona Server moved to https://jira.percona.com/projects/PS 5.6.33-79.0
5.7	Invalid	Undecided	Unassigned

Bug Description

If server is shutdown immediately after HandlerSocket plugin has initialized, it may hit a race condition between worker thread initialisation, which happens asynchronously, and at some point adds threads to the server global thread list, and server shutdown, which waits for the thread count to go down to zero. This race condition may result in some worker threads not receiving kill notifications, and thus hanging the server shutdown

On 5.6 trunk:

main.handler_socket w1 [ fail ]
Test ended at 2016-08-25 08:24:42

CURRENT_TEST: main.handler_socket
--- /mnt/workspace/percona-server-5.6-trunk/BUILD_TYPE/release/Host/ubuntu-precise-32bit/mysql-test/r/handler_socket.result 2016-08-25 14:53:53.197025000 +0300
+++ /mnt/workspace/percona-server-5.6-trunk/BUILD_TYPE/release/Host/ubuntu-precise-32bit/build/mysql-test/var/1/log/handler_socket.reject 2016-08-25 15:24:42.525025000 +0300
@@ -1,4 +1,5 @@
call mtr.add_suppression("handlersocket: open_files_limit is too small");
INSTALL PLUGIN handlersocket SONAME 'HANDLER_SOCKET';
Restarting mysqld for bug 1397859 test...
+shutdown_server timeout 60 exceeded, SIGKILL sent to the server
UNINSTALL PLUGIN handlersocket;

See original description

Tags:

Laurynas Biveinis (laurynas-biveinis) on 2016-08-26

tags:

added: ci handlersocket

Laurynas Biveinis (laurynas-biveinis) on 2016-09-06

summary:	- Test main.handler_socket is unstable + Intermittently stalled shutdown if it's issued immediately after + HandlerSocket startup
description:	updated
description:	updated
tags:	added: upstream

Revision history for this message

Laurynas Biveinis (laurynas-biveinis) wrote on 2016-09-06: Re: Intermittently stalled shutdown if it's issued immediately after HandlerSocket startup

The same race condition may also result in a crash:

Core was generated by `/home/laurynas/obj-percona-5.6-debug/sql/mysqld-debug --defaults-group-suffix=.'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 __pthread_kill (threadid=<optimized out>, signo=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
62 ../sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
[Current thread is 1 (Thread 0x7f577a7f4700 (LWP 14317))]
#0 __pthread_kill (threadid=<optimized out>, signo=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
#1 0x0000000000b0ea3e in my_write_core (sig=11) at /home/laurynas/mysql-server/mysys/stacktrace.c:422
#2 0x000000000074c599 in handle_fatal_signal (sig=11) at /home/laurynas/mysql-server/sql/signal_handler.cc:236
#3 <signal handler called>
#4 0x000000000062da10 in inline_mysql_rwlock_rdlock (that=0x8, src_file=0xf591c8 "/home/laurynas/mysql-server/sql/rpl_gtid.h", src_line=347) at /home/laurynas/mysql-server/include/mysql/psi/mysql_thread.h:856
#5 0x00000000006413c0 in Checkable_rwlock::rdlock (this=0x0) at /home/laurynas/mysql-server/sql/rpl_gtid.h:347
#6 0x0000000000a546d9 in gtid_rollback (thd=0x7f578412bfc0) at /home/laurynas/mysql-server/sql/rpl_gtid_execution.cc:454
#7 0x0000000000651d91 in ha_rollback_trans (thd=0x7f578412bfc0, all=true) at /home/laurynas/mysql-server/sql/handler.cc:1716
#8 0x00000000008e95c1 in trans_rollback (thd=0x7f578412bfc0) at /home/laurynas/mysql-server/sql/transaction.cc:334
#9 0x00000000007babed in THD::cleanup (this=0x7f578412bfc0) at /home/laurynas/mysql-server/sql/sql_class.cc:1706
#10 0x00000000007bafba in THD::release_resources (this=0x7f578412bfc0) at /home/laurynas/mysql-server/sql/sql_class.cc:1792
#11 0x00007f57a61f2e0c in dena::dbcontext::term_thread (this=0x7f57840c51b0) at /home/laurynas/mysql-server/plugin/HandlerSocket-Plugin-for-MySQL/handlersocket/database.cpp:356
#12 0x00007f57a6200916 in dena::(anonymous namespace)::thr_init::~thr_init (this=0x7f577a7f3e80, __in_chrg=<optimized out>) at /home/laurynas/mysql-server/plugin/HandlerSocket-Plugin-for-MySQL/handlersocket/hstcpsvr_worker.cpp:314
#13 0x00007f57a6200ab1 in dena::hstcpsvr_worker::run (this=0x7f57840c50f0) at /home/laurynas/mysql-server/plugin/HandlerSocket-Plugin-for-MySQL/handlersocket/hstcpsvr_worker.cpp:324
#14 0x00007f57a620b495 in dena::worker_throbj::operator() (this=0x7f57840c50c0) at /home/laurynas/mysql-server/plugin/HandlerSocket-Plugin-for-MySQL/handlersocket/hstcpsvr.cpp:32
#15 0x00007f57a620ccf2 in dena::thread<dena::worker_throbj>::thread_main (arg=0x7f57840c50c0) at /home/laurynas/mysql-server/plugin/HandlerSocket-Plugin-for-MySQL/libhsclient/thread.hpp:71
#16 0x00007f57ab9b96fa in start_thread (arg=0x7f577a7f4700) at pthread_create.c:333
#17 0x00007f57aae4eb5d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

The same race condition may also result in a crash:

Core was generated by `/home/laurynas/obj-percona-5.6-debug/sql/mysqld-debug --defaults-group-suffix=.'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  __pthread_kill (threadid=<optimized out>, signo=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
62	../sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
[Current thread is 1 (Thread 0x7f577a7f4700 (LWP 14317))]
#0  __pthread_kill (threadid=<optimized out>, signo=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
#1  0x0000000000b0ea3e in my_write_core (sig=11) at /home/laurynas/mysql-server/mysys/stacktrace.c:422
#2  0x000000000074c599 in handle_fatal_signal (sig=11) at /home/laurynas/mysql-server/sql/signal_handler.cc:236
#3  <signal handler called>
#4  0x000000000062da10 in inline_mysql_rwlock_rdlock (that=0x8, src_file=0xf591c8 "/home/laurynas/mysql-server/sql/rpl_gtid.h", src_line=347) at /home/laurynas/mysql-server/include/mysql/psi/mysql_thread.h:856
#5  0x00000000006413c0 in Checkable_rwlock::rdlock (this=0x0) at /home/laurynas/mysql-server/sql/rpl_gtid.h:347
#6  0x0000000000a546d9 in gtid_rollback (thd=0x7f578412bfc0) at /home/laurynas/mysql-server/sql/rpl_gtid_execution.cc:454
#7  0x0000000000651d91 in ha_rollback_trans (thd=0x7f578412bfc0, all=true) at /home/laurynas/mysql-server/sql/handler.cc:1716
#8  0x00000000008e95c1 in trans_rollback (thd=0x7f578412bfc0) at /home/laurynas/mysql-server/sql/transaction.cc:334
#9  0x00000000007babed in THD::cleanup (this=0x7f578412bfc0) at /home/laurynas/mysql-server/sql/sql_class.cc:1706
#10 0x00000000007bafba in THD::release_resources (this=0x7f578412bfc0) at /home/laurynas/mysql-server/sql/sql_class.cc:1792
#11 0x00007f57a61f2e0c in dena::dbcontext::term_thread (this=0x7f57840c51b0) at /home/laurynas/mysql-server/plugin/HandlerSocket-Plugin-for-MySQL/handlersocket/database.cpp:356
#12 0x00007f57a6200916 in dena::(anonymous namespace)::thr_init::~thr_init (this=0x7f577a7f3e80, __in_chrg=<optimized out>) at /home/laurynas/mysql-server/plugin/HandlerSocket-Plugin-for-MySQL/handlersocket/hstcpsvr_worker.cpp:314
#13 0x00007f57a6200ab1 in dena::hstcpsvr_worker::run (this=0x7f57840c50f0) at /home/laurynas/mysql-server/plugin/HandlerSocket-Plugin-for-MySQL/handlersocket/hstcpsvr_worker.cpp:324
#14 0x00007f57a620b495 in dena::worker_throbj::operator() (this=0x7f57840c50c0) at /home/laurynas/mysql-server/plugin/HandlerSocket-Plugin-for-MySQL/handlersocket/hstcpsvr.cpp:32
#15 0x00007f57a620ccf2 in dena::thread<dena::worker_throbj>::thread_main (arg=0x7f57840c50c0) at /home/laurynas/mysql-server/plugin/HandlerSocket-Plugin-for-MySQL/libhsclient/thread.hpp:71
#16 0x00007f57ab9b96fa in start_thread (arg=0x7f577a7f4700) at pthread_create.c:333
#17 0x00007f57aae4eb5d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Laurynas Biveinis (laurynas-biveinis) on 2016-09-06

summary:

- Intermittently stalled shutdown if it's issued immediately after
- HandlerSocket startup
+ Intermittently stalled or crashing shutdown if it's issued immediately
+ after HandlerSocket startup

Revision history for this message

Laurynas Biveinis (laurynas-biveinis) wrote on 2016-09-06:

https://github.com/percona/percona-server/pull/980
https://github.com/percona/percona-server/pull/981