Bug #74956 Can not stop mysql with memcached plugin
Submitted: 21 Nov 2014 10:11 Modified: 19 Jan 2015 13:49
Reporter: Nilnandan Joshi Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Memcached Severity:S2 (Serious)
Version:5.6.21, 5.6.23 OS:Linux (CentOS 6.5)
Assigned to: CPU Architecture:Any

[21 Nov 2014 10:11] Nilnandan Joshi
Description:
Simply install/configure memcached plugin with this
http://dev.mysql.com/doc/refman/5.6/en/innodb-memcached-snifftest.html

and check below, how to repeat. 

How to repeat:
[root@centos65 mysql]# mysql 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 5
Server version: 5.6.21-log MySQL Community Server (GPL)

Copyright (c) 2000, 2014, Oracle and/or its affiliates. All rights reserved.

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> show plugins;
+----------------------------+----------+--------------------+-----------------+---------+
| Name                       | Status   | Type               | Library         | License |
+----------------------------+----------+--------------------+-----------------+---------+
| binlog                     | ACTIVE   | STORAGE ENGINE     | NULL            | GPL     |
...
| daemon_memcached           | ACTIVE   | DAEMON             | libmemcached.so | GPL     |
+----------------------------+----------+--------------------+-----------------+---------+
43 rows in set (0.01 sec)

mysql> 
mysql> show variables like '%memcached%';
+----------------------------------+------------------+
| Variable_name                    | Value            |
+----------------------------------+------------------+
| daemon_memcached_enable_binlog   | OFF              |
| daemon_memcached_engine_lib_name | innodb_engine.so |
| daemon_memcached_engine_lib_path |                  |
| daemon_memcached_option          | -m               |
| daemon_memcached_r_batch_size    | 1                |
| daemon_memcached_w_batch_size    | 1                |
+----------------------------------+------------------+
6 rows in set (0.01 sec)

mysql> 
mysql> show variables like 'innodb_api%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| innodb_api_bk_commit_interval | 5     |
| innodb_api_disable_rowlock    | OFF   |
| innodb_api_enable_binlog      | ON    | -- this should be on
| innodb_api_enable_mdl         | OFF   |
| innodb_api_trx_level          | 0     |
+-------------------------------+-------+
5 rows in set (0.00 sec)
[root@centos65 mysql]# telnet 127.0.0.1 11211
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
set test 0 3600 4
1234
STORED
get test
VALUE test 0 4
1234
END
quit
Connection closed by foreign host.
[root@centos65 mysql]# 
[root@centos65 mysql]# /etc/init.d/mysqld stop
Stopping mysqld:                                           [  OK  ]
[root@centos65 mysql]# ps -ef | grep mysql
root      1761     1  0 15:12 pts/0    00:00:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --socket=/var/lib/mysql/mysql.sock --pid-file=/var/run/mysqld/mysqld.pid --basedir=/usr --user=mysql
mysql     2476  1761  7 15:19 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/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
root      2515  1712  0 15:19 pts/0    00:00:00 grep mysql
[root@centos65 mysql]# 

nothing in error log.
[21 Nov 2014 19:15] Umesh Shastry
Hello Nilnandan Joshi,

Thank you for the report.
Verified as described.

Thanks,
Umesh
[21 Nov 2014 19:15] Umesh Shastry
// 5.6.21

[root@ushastry ushastry]# cat /etc/*release
CentOS release 6.5 (Final)
LSB_VERSION=base-4.0-amd64:base-4.0-noarch:core-4.0-amd64:core-4.0-noarch:graphics-4.0-amd64:graphics-4.0-noarch:printing-4.0-amd64:printing-4.0-noarch
CentOS release 6.5 (Final)
CentOS release 6.5 (Final)

[root@ushastry ushastry]# rpm -qa|grep -i mysql
MySQL-shared-5.6.21-1.el6.x86_64
MySQL-client-5.6.21-1.el6.x86_64
mysql-utilities-1.4.3-1.el6.noarch
MySQL-devel-5.6.21-1.el6.x86_64
MySQL-server-5.6.21-1.el6.x86_64
MySQL-test-5.6.21-1.el6.x86_64
MySQL-embedded-5.6.21-1.el6.x86_64

[root@ushastry ushastry]# /etc/init.d/mysql stop
Shutting down MySQL........................................[  OK  ].
[root@ushastry ushastry]# ps aux|grep mysqld
root      4362  0.0  0.0 106232  1448 pts/0    S    00:38   0:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --pid-file=/var/lib/mysql/ushastry.pid --innodb_api_enable_binlog=1 --daemon_memcached_option=-m128 --log_bin
mysql     4691  9.8 15.4 1414780 456528 pts/0  Sl   00:40   0:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --innodb-api-enable-binlog=1 --daemon-memcached-option=-m128 --log-bin --log-error=/var/lib/mysql/ushastry.err --pid-file=/var/lib/mysql/ushastry.pid
root      4737  0.0  0.0 103252   824 pts/0    S+   00:40   0:00 grep mysqld
[root@ushastry ushastry]#
[21 Nov 2014 19:38] Umesh Shastry
// build details - binary tarballs

[ushastry@cluster-repo mysql-advanced-5.6.23]$ more docs/INFO_SRC
revision-id: michael.izioumtchenko@oracle.com-20141106152508-nntohvuco3v1rjjx
date: 2014-11-06 16:25:08 +0100
build-date: 2014-11-06 18:00:43 +0100
revno: 6243
branch-nick: daily-5.6
MySQL source 5.6.23

[ushastry@cluster-repo mysql-advanced-5.6.23]$ cat /etc/*release
LSB_VERSION=base-4.0-amd64:base-4.0-noarch:core-4.0-amd64:core-4.0-noarch:graphics-4.0-amd64:graphics-4.0-noarch:printing-4.0-amd64:printing-4.0-noarch
Oracle Linux Server release 6.6
Red Hat Enterprise Linux Server release 6.6 (Santiago)
Oracle Linux Server release 6.6

// Start up
[ushastry@cluster-repo mysql-advanced-5.6.23]$ /data/ushastry/server/mysql-advanced-5.6.23/bin/mysqld --basedir=/data/ushastry/server/mysql-advanced-5.6.23 --datadir=/tmp/bug --core --socket=/tmp/mysql.sock  --port=3306 --log-error=/tmp/bug/log.err --user=mysql 2>&1 &
[1] 9105
[ushastry@cluster-repo mysql-advanced-5.6.23]$ 2014-11-24 02:27:45 0 [Warning] Using unique option prefix core instead of core-file is deprecated and will be removed in a future release. Please use the full name instead.
2014-11-24 02:27:45 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-11-24 02:27:45 9105 [Warning] One can only use the --user switch if running as root

[ushastry@cluster-repo mysql-advanced-5.6.23]$
[ushastry@cluster-repo mysql-advanced-5.6.23]$ bin/mysql -u root -p < share/innodb_memcached_config.sql
Enter password:
[ushastry@cluster-repo mysql-advanced-5.6.23]$ bin/mysql -u root -p
Enter password:
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.6.23-enterprise-commercial-advanced MySQL Enterprise Server - Advanced Edition (Commercial)

Copyright (c) 2000, 2014, Oracle and/or its affiliates. All rights reserved.

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 daemon_memcached soname "libmemcached.so";
Query OK, 0 rows affected (0.00 sec)

mysql> show plugins;
+----------------------------+----------+--------------------+-----------------+-------------+
| Name                       | Status   | Type               | Library         | License     |
+----------------------------+----------+--------------------+-----------------+-------------+
| binlog                     | ACTIVE   | STORAGE ENGINE     | NULL            | PROPRIETARY |
.
| partition                  | ACTIVE   | STORAGE ENGINE     | NULL            | PROPRIETARY |
| daemon_memcached           | ACTIVE   | DAEMON             | libmemcached.so | PROPRIETARY |
+----------------------------+----------+--------------------+-----------------+-------------+
43 rows in set (0.00 sec)

mysql>

// restart mysql with --innodb_api_enable_binlog=1 --daemon_memcached_option='-m128' --log_bin

mysql> show variables like '%memcached%';
+----------------------------------+------------------+
| Variable_name                    | Value            |
+----------------------------------+------------------+
| daemon_memcached_enable_binlog   | OFF              |
| daemon_memcached_engine_lib_name | innodb_engine.so |
| daemon_memcached_engine_lib_path |                  |
| daemon_memcached_option          | -m128            |
| daemon_memcached_r_batch_size    | 1                |
| daemon_memcached_w_batch_size    | 1                |
+----------------------------------+------------------+
6 rows in set (0.00 sec)

mysql> show variables like 'innodb_api%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| innodb_api_bk_commit_interval | 5     |
| innodb_api_disable_rowlock    | OFF   |
| innodb_api_enable_binlog      | ON    |
| innodb_api_enable_mdl         | OFF   |
| innodb_api_trx_level          | 0     |
+-------------------------------+-------+
5 rows in set (0.00 sec)

// telnet session

[root@cluster-repo mysql-advanced-5.6.23]# telnet 127.0.0.1 11211
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
stats
STAT pid 9183
STAT uptime 71
STAT time 1416776491
STAT version 5.6.23
STAT libevent 5.6.23
..

set test 0 3600 4
1234
STORED
quit
Connection closed by foreign host.

[root@cluster-repo mysql-advanced-5.6.23]# ps aux|grep mysqld
ushastry  9183  0.3  1.8 1023184 112924 pts/1  Sl   02:30   0:00 /data/ushastry/server/mysql-advanced-5.6.23/bin/mysqld --basedir=/data/ushastry/server/mysql-advanced-5.6.23 --datadir=/tmp/bug --core --socket=/tmp/mysql.sock --port=3306 --log-error=/tmp/bug/log.err --user=mysql --innodb_api_enable_binlog=1 --daemon_memcached_option=-m128 --log_bin
root      9222  0.0  0.0 103252   828 pts/0    S+   02:32   0:00 grep mysqld
[root@cluster-repo mysql-advanced-5.6.23]#
[root@cluster-repo mysql-advanced-5.6.23]# bin/mysqladmin -u root -p shutdown
Enter password:

^^^^^^^^^^^^ shutdown hanged 

[1]+  Segmentation fault      (core dumped) /data/ushastry/server/mysql-advanced-5.6.23/bin/mysqld --basedir=/data/ushastry/server/mysql-advanced-5.6.23 --datadir=/tmp/bug --core --socket=/tmp/mysql.sock --port=3306 --log-error=/tmp/bug/log.err --user=mysql --innodb_api_enable_binlog=1 --daemon_memcached_option='-m128' --log_bin 2>&1

(gdb) bt
#0  0x00000038f1c0f867 in ?? () from /lib64/libgcc_s.so.1
#1  0x00000038f1c101f0 in ?? () from /lib64/libgcc_s.so.1
#2  0x00000038f1c102b4 in _Unwind_ForcedUnwind () from /lib64/libgcc_s.so.1
#3  0x0000003deb00de90 in __pthread_unwind (buf=<value optimized out>) at unwind.c:130
#4  0x0000003deb00e1a5 in __pthread_enable_asynccancel () at ../nptl/sysdeps/unix/sysv/linux/x86_64/cancellation.S:81
#5  0x0000003deb00e6f2 in write () at ../sysdeps/unix/syscall-template.S:82
#6  0x0000000000903a25 in my_safe_printf_stderr (fmt=<value optimized out>) at /export/home/pb2/build/sb_0-13622626-1415294505.52/mysqlcom-pro-5.6.23/mysys/stacktrace.c:913
#7  0x0000000000696a9e in handle_fatal_signal (sig=11) at /export/home/pb2/build/sb_0-13622626-1415294505.52/mysqlcom-pro-5.6.23/sql/signal_handler.cc:90
#8  <signal handler called>
#9  0x00007f1899d7e768 in ?? ()
#10 0x0000000000000000 in ?? ()
[21 Nov 2014 19:42] Umesh Shastry
// forceful exit

[root@cluster-repo mysql-advanced-5.6.23]# bin/mysqladmin -u root -p shutdown
Enter password:
^CWarning;  Aborted waiting on pid file: '/tmp/bug/cluster-repo.pid' after 807 seconds
[13 Jan 2015 8:53] Allen Lai
Posted by developer:
 
It's a regression introduced by fixing bug#18409840 MEMCACHED_SHUTDOWN IS CALLING "PLUGIN_DEL" WITHOUT ACQUIRING LOCK_PLUGIN MUTEX..
The acquiring lock causes deadlock, we should move this acquiring lock after calling plugin_deinitialize.
[19 Jan 2015 13:49] Daniel Price
Fixed as of the upcoming 5.6.23, 5.7.6 releases, and here's the changelog entry:

Due to a regression introduced in MySQL 5.6.20, "mysqld stop" would not
stop the "mysqld" server process while the "InnoDB" "memcached" plugin was
active. 

Thank you for the bug report.
[20 Jan 2015 12:31] Daniel Price
For 5.6, the bug fix was applied to 5.6.24:

Fixed as of the upcoming 5.6.24, 5.7.6 releases, and here's the changelog
entry:

Due to a regression introduced in MySQL 5.6.20, "mysqld stop" would not
stop the "mysqld" server process while the "InnoDB" "memcached" plugin was
active.

Thank you for the bug report.
[27 Apr 2015 7:51] Laurynas Biveinis
commit ef036b151bf1a3b65b897d88b2cd03e9bea630ac
Author: Allen.Lai <zheng.lai@oracle.com>
Date:   Thu Jan 15 11:40:59 2015 +0800

    Bug#20078646 CAN NOT STOP MYSQL WITH MEMCACHED PLUGIN
    
    It's a regression introduced by fixing bug#18409840 MEMCACHED_SHUTDOWN
    IS CALLING "PLUGIN_DEL" WITHOUT ACQUIRING LOCK_PLUGIN MUTEX.
    The acquiring lock causes deadlock, we should move this acquiring lock after
    calling plugin_deinitialize.
    
    Reviewed-by: Jimmy Yang<jimmy.yang@oracle.com> via IM