Bug #1319904 “5.5 mysqld daemon with installed handlersocket plu...” : Bugs : Percona Server moved to https://jira.percona.com/projects/PS

Nikolai (korolev-n) on 2014-05-21

description:

updated

Revision history for this message

Valerii Kravchuk (valerii-kravchuk) wrote on 2014-05-22:

#2

Download full text (6.8 KiB)

Confirmed on Ubuntu:

openxs@ao756:~$ mysql -uroot -proot test
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 37
Server version: 5.5.37-35.0-657.saucy (Ubuntu)

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

Confirmed on Ubuntu:

openxs@ao756:~$ mysql -uroot -proot test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 37
Server version: 5.5.37-35.0-657.saucy (Ubuntu)

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> exit
Bye
openxs@ao756:~$ ps aux | grep mysqld
root     24591  0.0  0.0   4440   760 pts/1    S    13:18   0:00 /bin/sh /usr/bin/mysqld_safe
mysql    24683  0.4  1.1 1469000 44224 pts/1   Sl   13:18   0:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=/var/lib/mysql/ao756.err --pid-file=/var/lib/mysql/ao756.pid
openxs   24889  0.0  0.0  15092   992 pts/1    S+   13:19   0:00 grep --color=auto mysqld
openxs@ao756:~$ sudo kill -15 `pidof mysqld`
openxs@ao756:~$ ps aux | grep mysqld
root     24591  0.0  0.0   4440   760 pts/1    S    13:18   0:00 /bin/sh /usr/bin/mysqld_safe
mysql    24683  0.3  1.1 1469000 44224 pts/1   Sl   13:18   0:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=/var/lib/mysql/ao756.err --pid-file=/var/lib/mysql/ao756.pid
openxs   24897  0.0  0.0  15092   988 pts/1    S+   13:20   0:00 grep --color=auto mysqld
openxs@ao756:~$ sudo service mysql stop
 * Stopping MySQL (Percona Server) mysqld
... (it hangs) ...

Laurynas Biveinis (laurynas-biveinis) on 2014-05-23

tags:

added: handlersocket

Revision history for this message

Serge (laaxags) wrote on 2014-06-16:

#3

With all respect to Percona - but why use third-party HandlerSocket instead of an own Percona solution ?

Percona developers could create a native Percona plugin what allows to perform the some of MySQL operations (simple ones only) like SELECT or INSERT - but applying to MySQL as NoSQL - same what HandlerSocket does.

It can be used by own Percona syntax for such commands, let's say
SELECT id, title, date - applies to MySQL using standard way, but specific syntax like
SELECTNS id, title,date - or - INSERTNS id, title,date - Percona understands as NoSQL query and perform it accordingly using a native analog of HandlerSocket.

It would be ideal for simple only bulk operations.
Just an idea, but why not ?
Great successes to Percona team anyway !

Revision history for this message

Gene Vayngrib (gene-vayngrib-lablz) wrote on 2014-06-20:

#4

I can confirm on Ubuntu 14.04 the same problem
But it appears to be much worse as Percona 5.5.37 seems to come with handlersocket installed by default. So all I did was install Percona and now can't stop the server. As this is part of our automatic install script for EC2 machine bootstrapping, this bug kills the whole procedure. Any idea when will it be fixed?

Btw, tried Percona 5.6, but it has another problem, it crashes during the inplace database recovery (of the database created by Percona 5.5.).

Revision history for this message

Valerii Kravchuk (valerii-kravchuk) wrote on 2014-06-21:

#5

Download full text (7.1 KiB)

I can not reproduce this with 5.6 on CentOS:

[openxs@centos ~]$ ps aux | grep mysqld
root 1139 0.0 0.1 108300 1624 ? S 19:01 0:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --pid-file=/var/lib/mysql/centos.pid
mysql 1408 0.4 29.9 1126148 460864 ? Sl 19:01 0:07 /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/centos.pid --socket=/var/lib/mysql/mysql.sock
openxs 1561 0.0 0.0 103244 848 pts/0 S+ 19:25 0:00 grep mysqld
[openxs@centos ~]$ mysql -uroot test
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.17-66.0 Percona Server (GPL), Release 66.0, Revision 608

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> INSTALL PLUGIN handlersocket SONAME 'handlersocket.so';
Query OK, 0 rows affected (0.07 sec)

mysql> exit
Bye
[openxs@centos ~]$ su
Password:
[root@centos openxs]# service mysql stop
Shutting down MySQL (Percona Server).. SUCCESS!
[root@centos openxs]# vi /etc/my.cnf
[root@centos openxs]# grep handler /etc/my.cnf
loose_handlersocket_port=9998
[root@centos openxs]# service mysql start
Starting MySQL (Percona Server)... SUCCESS!
[root@centos openxs]# kill -15 `pidof mysqld`
[root@centos openxs]# ps aux | grep mysqld
root 1932 0.0 0.0 103244 844 pts/0 S+ 19:27 0:00 grep mysqld
[root@centos openxs]# service mysql start
Starting MySQL (Percona Server)... SUCCESS!
[root@centos openxs]# mysql -uroot test
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.17-66.0 Percona Server (GPL), Release 66.0, Revision 608

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

I can not reproduce this with 5.6 on CentOS:

[openxs@centos ~]$ ps aux | grep mysqld
root      1139  0.0  0.1 108300  1624 ?        S    19:01   0:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --pid-file=/var/lib/mysql/centos.pid
mysql     1408  0.4 29.9 1126148 460864 ?      Sl   19:01   0:07 /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/centos.pid --socket=/var/lib/mysql/mysql.sock
openxs    1561  0.0  0.0 103244   848 pts/0    S+   19:25   0:00 grep mysqld
[openxs@centos ~]$ mysql -uroot test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.17-66.0 Percona Server (GPL), Release 66.0, Revision 608

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> INSTALL PLUGIN handlersocket SONAME 'handlersocket.so';
Query OK, 0 rows affected (0.07 sec)

mysql> exit
Bye
[openxs@centos ~]$ su
Password:
[root@centos openxs]# service mysql stop
Shutting down MySQL (Percona Server).. SUCCESS!
[root@centos openxs]# vi /etc/my.cnf
[root@centos openxs]# grep handler /etc/my.cnf
loose_handlersocket_port=9998
[root@centos openxs]# service mysql start
Starting MySQL (Percona Server)... SUCCESS!
[root@centos openxs]# kill -15 `pidof mysqld`
[root@centos openxs]# ps aux | grep mysqld
root      1932  0.0  0.0 103244   844 pts/0    S+   19:27   0:00 grep mysqld
[root@centos openxs]# service mysql start
Starting MySQL (Percona Server)... SUCCESS!
[root@centos openxs]# mysql -uroot test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.17-66.0 Percona Server (GPL), Release 66.0, Revision 608

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

As for that "another problem" of crash, it's a topic for a separate bug report.

Revision history for this message

Laurynas Biveinis (laurynas-biveinis) wrote on 2014-06-21:

#6

IMHO PS 5.5 mysqld ignoring SIGTERM by default (because HS is installed by default) warrants a priority bump.

Revision history for this message

Lisio (lisio) wrote on 2014-06-22:

#7

How to reproduce on Ubuntu 14.04:

Add Percona repositories to apt sources:
    deb http://repo.percona.com/apt trusty main
    deb-src http://repo.percona.com/apt trusty main
Install Percona XtraDB Cluster
    apt-get install percona-xtradb-cluster-55 percona-xtradb-cluster-galera-2 percona-xtradb-cluster-galera-2.x
Add HandlerSocket config lines to /etc/mysql/my.cnf
    loose_handlersocket_port = 9998
    loose_handlersocket_port_wr = 9999
Start mysql service
    service mysql start
Stop mysql service
    service mysql stop
Wait for years

Revision history for this message

markus_albe (markus-albe) wrote on 2014-11-26:

#8

Download full text (4.0 KiB)

Customer reproduced with 5.6.21 and I verified through code inspection:

Error log showed

2014-11-25 05:16:14 31200 [Note] /usr/sbin/mysqld: Normal shutdown
2014-11-25 05:16:14 31200 [Note] Giving 24 client threads a chance to die gracefully
2014-11-25 05:16:14 31200 [Note] Event Scheduler: Purging the queue. 0 events
2014-11-25 05:16:14 31200 [Note] Shutting down slave threads
2014-11-25 05:16:16 31200 [Note] Forcefully disconnecting 24 remaining clients

Then pmp showed:
23 __lll_lock_wait(libpthread.so.0),_L_lock_995(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),dena::dbcontext::term_thread(handlersocket.so),dena::hstcpsvr_worker::run(handlersocket.so),dena::thread::thread_main(handlersocket.so),start_thread(libpthread.so.0),clone(libc.so.6)

1 __lll_lock_wait(libpthread.so.0),_L_lock_995(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),remove_global_thread,dena::dbcontext::term_thread(handlersocket.so),dena::hstcpsvr_worker::run(handlersocket.so),dena::thread::thread_main(handlersocket.so),start_thread(libpthread.so.0),clone(libc.so.6)

Definition of dena::dbcontext::term_thread (from https://github.com/DeNA/HandlerSocket-Plugin-for-MySQL/blob/master/handlersocket/database.cpp#L346):

dbcontext::term_thread()
{
DBG_THR(fprintf(stderr, "HNDSOCK thread end %p\n", thd));
unlock_tables_if();
my_pthread_setspecific_ptr(THR_THD, 0);
{
pthread_mutex_lock(&LOCK_thread_count);
#if MYSQL_VERSION_ID >= 50600
remove_global_thread(thd);
#else
--thread_count;
#endif
delete thd;
thd = 0;
pthread_mutex_unlock(&LOCK_thread_count);
my_thread_end();
}
}

And definition of remove_global_thread (from 5.6.21/sql/mysqld.cc@892):

void remove_global_thread(THD *thd)
{
  DBUG_PRINT("info", ("remove_global_thread %p current_linfo %p",
                      thd, thd->current_linfo));
  mysql_mutex_lock(&LOCK_thd_remove);
  mysql_mutex_lock(&LOCK_thread_count);
  DBUG_ASSERT(thd->release_resources_done());
  /*
    Used by binlog_reset_master. It would be cleaner to use
    DEBUG_SYNC here, but that's not possible because the THD's debug
    sync feature has been shut down at this point.
   */
  DBUG_EXECUTE_IF("sleep_after_lock_thread_count_before_delete_thd",
                  sleep(5););

  const size_t num_erased= global_thread_list->erase(thd);
  if (num_erased == 1)
    --global_thread_count;
  // Removing a THD that was never added is an error.
  DBUG_ASSERT(1 == num_erased);

  mysql_mutex_unlock(&LOCK_thd_remove);
  mysql_cond_broadcast(&COND_thread_count);
  mysql_mutex_unlock(&LOCK_thread_count);
}

So my understanding is that the second time this tries to acquire the mutex here (mysql_mutex_lock(&LOCK_thread_count)) it will wait forever because LOCK_thread_count is not a recursive mutex (thanks Vlad for input about that):

fgrep -RnI --exclude-dir=build* --exclude-dir=mysql-test --exclude=tags --exclude=*.P* --exclude=*.T* "LOCK_thread_count" . | grep init
./tests/thread_test.c:196: pthread_mutex_init(&LOCK_thread_count,MY_MUTEX_INIT_FAST);
./sql/mysqld.cc:3638: mysql_mutex_init(key_LOCK_thread_count, &LOCK_thread_count, MY_MUTEX_INIT_FAST);
./mysys/thr_lock.c:1608: if ((error= mysql_mutex_init(0, &LOCK_thread_count, MY_MUTEX_INIT_F...

Customer reproduced with 5.6.21 and I verified through code inspection:

Error log showed

2014-11-25 05:16:14 31200 [Note] /usr/sbin/mysqld: Normal shutdown
2014-11-25 05:16:14 31200 [Note] Giving 24 client threads a chance to die gracefully
2014-11-25 05:16:14 31200 [Note] Event Scheduler: Purging the queue. 0 events
2014-11-25 05:16:14 31200 [Note] Shutting down slave threads
2014-11-25 05:16:16 31200 [Note] Forcefully disconnecting 24 remaining clients

Then pmp showed:
23 __lll_lock_wait(libpthread.so.0),_L_lock_995(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),dena::dbcontext::term_thread(handlersocket.so),dena::hstcpsvr_worker::run(handlersocket.so),dena::thread::thread_main(handlersocket.so),start_thread(libpthread.so.0),clone(libc.so.6)

1 __lll_lock_wait(libpthread.so.0),_L_lock_995(libpthread.so.0),pthread_mutex_lock(libpthread.so.0),remove_global_thread,dena::dbcontext::term_thread(handlersocket.so),dena::hstcpsvr_worker::run(handlersocket.so),dena::thread::thread_main(handlersocket.so),start_thread(libpthread.so.0),clone(libc.so.6)

Definition of dena::dbcontext::term_thread (from https://github.com/DeNA/HandlerSocket-Plugin-for-MySQL/blob/master/handlersocket/database.cpp#L346):

dbcontext::term_thread()
{
DBG_THR(fprintf(stderr, "HNDSOCK thread end %p\n", thd));
unlock_tables_if();
my_pthread_setspecific_ptr(THR_THD, 0);
{
pthread_mutex_lock(&LOCK_thread_count);
#if MYSQL_VERSION_ID >= 50600
remove_global_thread(thd);
#else
--thread_count;
#endif
delete thd;
thd = 0;
pthread_mutex_unlock(&LOCK_thread_count);
my_thread_end();
}
}

And definition of remove_global_thread (from 5.6.21/sql/mysqld.cc@892):

void remove_global_thread(THD *thd)
{
  DBUG_PRINT("info", ("remove_global_thread %p current_linfo %p",
                      thd, thd->current_linfo));
  mysql_mutex_lock(&LOCK_thd_remove);
  mysql_mutex_lock(&LOCK_thread_count);
  DBUG_ASSERT(thd->release_resources_done());
  /*
    Used by binlog_reset_master.  It would be cleaner to use
    DEBUG_SYNC here, but that's not possible because the THD's debug
    sync feature has been shut down at this point.
   */
  DBUG_EXECUTE_IF("sleep_after_lock_thread_count_before_delete_thd",
                  sleep(5););

const size_t num_erased= global_thread_list->erase(thd);
  if (num_erased == 1)
    --global_thread_count;
  // Removing a THD that was never added is an error.
  DBUG_ASSERT(1 == num_erased);

mysql_mutex_unlock(&LOCK_thd_remove);
  mysql_cond_broadcast(&COND_thread_count);
  mysql_mutex_unlock(&LOCK_thread_count);
}

So my understanding is that the second time this tries to acquire the mutex here (mysql_mutex_lock(&LOCK_thread_count)) it will wait forever because  LOCK_thread_count is not a recursive mutex (thanks Vlad for input about that):

fgrep -RnI --exclude-dir=build* --exclude-dir=mysql-test --exclude=tags --exclude=*.P* --exclude=*.T* "LOCK_thread_count" . | grep init
./tests/thread_test.c:196:  pthread_mutex_init(&LOCK_thread_count,MY_MUTEX_INIT_FAST);
./sql/mysqld.cc:3638:  mysql_mutex_init(key_LOCK_thread_count, &LOCK_thread_count, MY_MUTEX_INIT_FAST);
./mysys/thr_lock.c:1608:  if ((error= mysql_mutex_init(0, &LOCK_thread_count, MY_MUTEX_INIT_FAST)))
./mysys/thr_alarm.c:883:  mysql_mutex_init(0, &LOCK_thread_count, MY_MUTEX_INIT_FAST);

About MY_MUTEX_INIT_FAST:

#ifdef PTHREAD_ADAPTIVE_MUTEX_INITIALIZER_NP
extern pthread_mutexattr_t my_fast_mutexattr;
#define MY_MUTEX_INIT_FAST &my_fast_mutexattr
#else
#define MY_MUTEX_INIT_FAST   NULL
#endif
...
#ifdef PTHREAD_ADAPTIVE_MUTEX_INITIALIZER_NP
  /*
    Set mutex type to "fast" a.k.a "adaptive"
    In this case the thread may steal the mutex from some other thread
    that is waiting for the same mutex.  This will save us some
    context switches but may cause a thread to 'starve forever' while
    waiting for the mutex (not likely if the code within the mutex is
    short).
  */
  pthread_mutexattr_init(&my_fast_mutexattr);
  pthread_mutexattr_settype(&my_fast_mutexattr,
                            PTHREAD_MUTEX_ADAPTIVE_NP);
#endif

tags:

added: i48431

Revision history for this message

Laurynas Biveinis (laurynas-biveinis) wrote on 2014-11-26:

#9

Markus, can you report this upstream?

Revision history for this message

markus_albe (markus-albe) wrote on 2014-11-27:

#10

Upstream: http://bugs.mysql.com/75028

Revision history for this message

Laurynas Biveinis (laurynas-biveinis) wrote on 2014-11-28:

#11

Markus, sorry, that would be the HandlerSocket upstream, not Oracle.

Revision history for this message

Laurynas Biveinis (laurynas-biveinis) wrote on 2014-11-28:

#12

The bug triggers only if HS is configured, merely installing the packages does not result in unstoppable server.

Raghavendra D Prabhu (raghavendra-prabhu) on 2014-11-28

tags:

added: pxc

Revision history for this message

Laurynas Biveinis (laurynas-biveinis) wrote on 2014-11-28:

#13

The 5.5 and 5.6 issues are different.

For 5.5, the shutdown hang is caused by mysqld signal handler never having its initialisation completed if HS is installed. That happens because both HS and signal_hand wait for COND_server_started, which is signalled using mysql_cond_signal, meaning that only one waiter is woken up, which happens to be the HS one. The signal handler waiter does not have a time out.

This is a regression introduced in the upstream fix for http://bugs.mysql.com/bug.php?id=62311, backported to our 5.5 as bug 1249193. The upstream 5.6 later fixed the regression as

$ bzr log -r 4754.1.1
------------------------------------------------------------
revno: 4754.1.1
committer: <email address hidden>
branch nick: 5.6-bug16315379
timestamp: Tue 2013-02-12 11:17:24 +0100
message:
  Bug#16315379 COND_SERVER_STARTED MAY HAVE MULTIPLE WAITERS
   - Always use pthread_cond_broadcast when signalling COND_server_started since there
     may be more than one thread waiting for the condition.

Laurynas Biveinis (laurynas-biveinis) on 2014-11-28

summary:

- mysqld daemon with installed handlersocket plugin did not stop
+ mysqld daemon with installed handlersocket plugin ignores any signals

Revision history for this message

Antony Dovgal (tony2001) wrote on 2014-11-28: Re: mysqld daemon with installed handlersocket plugin ignores any signals

#14

I went ahead and made a small patch fixing this issue: https://github.com/tony2001/HandlerSocket-Plugin-for-MySQL/commit/1301105ee54aaea3dc6f96d3bed00433076b3d4c
Pull request for the issue: https://github.com/DeNA/HandlerSocket-Plugin-for-MySQL/pull/104

Revision history for this message

Laurynas Biveinis (laurynas-biveinis) wrote on 2014-12-01:

#15

Since the 5.5 and 5.6 issues have different underlying cause, and different (although overlapping) user symptoms, I have moved the 5.6 one (comments #8 and #14) to a new bug 1397859. The current bug will remain about 5.5 only, as that issue was reported first.

summary:	- mysqld daemon with installed handlersocket plugin ignores any signals + 5.5 mysqld daemon with installed handlersocket plugin ignores any + signals
tags:	removed: i48431

Revision history for this message

Laurynas Biveinis (laurynas-biveinis) wrote on 2015-03-18:

#16

See bug 1402074

Revision history for this message

Shahriyar Rzayev (rzayev-sehriyar) wrote on 2018-01-25:

#17

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3139

	Status	Importance	Assigned to	Milestone
Percona Server moved to https://jira.percona.com/projects/PS	Invalid	Undecided	Unassigned
5.1	Invalid	Undecided	Unassigned
5.5	Fix Released	High	Laurynas Biveinis	Percona Server moved to https://jira.percona.com/projects/PS 5.5.41-37.0
5.6	Invalid	Undecided	Unassigned

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

5.5 mysqld daemon with installed handlersocket plugin ignores any signals

Bug Description

Duplicates of this bug

Other bug subscribers

Remote bug watches