MySQL Bugs: #41804: purge stored procedure cache causes mysterious hang for many minutes

Bug #41804	purge stored procedure cache causes mysterious hang for many minutes
Submitted:	31 Dec 2008 8:43	Modified:	7 Mar 2010 12:57
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Stored Routines	Severity:	S3 (Non-critical)
Version:	5.1.30	OS:	Windows
Assigned to:	Konstantin Osipov	CPU Architecture:	Any
Tags:	hang, stored procedure cache

Description:
On a moderately loaded system with many stored routines purging the stored program cache can take a long time.  During this time, queries appear to be hung, and there's no indication what is happening:

Client program was doing 80qps before purge.  During purge:
0121191 successful queries.  0009234 failed queries (0.000000 QPS).
0121191 successful queries.  0009234 failed queries (0.000000 QPS).
0121191 successful queries.  0009234 failed queries (0.000000 QPS).
0121193 successful queries.  0009234 failed queries (0.166667 QPS).
0121193 successful queries.  0009234 failed queries (0.000000 QPS).
<cut>

Query   |  277 | NULL      | CALL ` ...
Query   |  277 | NULL      | CALL ` ...
Query   |  131 | NULL      | CALL ` ...
Query   |  279 | NULL      | CALL ` ...
Query   |  191 | NULL      | CALL ` ...
Query   |  225 | NULL      | CALL ` ...
Query   |  223 | NULL      | CALL ` ...
Query   |  277 | NULL      | CALL ` ...
Query   |  279 | NULL      | CALL ` ...
Query   |  277 | NULL      | CALL ` ...

In this case it took a full 10 minutes to purge the cache.  After the purge is complete, you'd notice memory consumption of mysqld is much lower.

How to repeat:
create any 1000 stored routines.
call them all in multiple threads continuously.

after a few minutes, in a client session, purge the cache by running:
"drop procedure if exists p1;create procedure p1()begin end;"

now watch processlist and check if queries are hanging with NULL status.

Suggested fix:
Implement a faster way to purge SPs from the cache.  Query cache and innodb adaptive hash had same problems in the passed - not scaling to larger numbers of items during purge...

another symptom of this hang is when client connections quit (and they had called many stored routines).  they look like this in processlist:

+------+---------+------+-------+------------------+
| db   | Command | Time | State | Info             |
+------+---------+------+-------+------------------+
| test | Killed  |   41 | NULL  | NULL             |
| test | Killed  |   41 | NULL  | NULL             |
| test | Killed  |   36 | NULL  | NULL             |
| test | Killed  |   41 | NULL  | NULL             |
| test | Killed  |   41 | NULL  | NULL             |
| test | Killed  |   41 | NULL  | NULL             |
| test | Killed  |   41 | NULL  | NULL             |
| test | Killed  |   37 | NULL  | NULL             |
| test | Killed  |   38 | NULL  | NULL             |
| test | Killed  |   41 | NULL  | NULL             |
| test | Query   |    0 | NULL  | show processlist |

testcase

Attachment: bug41804.sql (application/unknown, text), 263.59 KiB.

I attached a testcase that shows the problem.  Paste it into mysql client.
It drop/create 3000 SPs.   Then it calls them all once, to populate the SP cache.

Then, it drops p1, which now has to invalidate entire cache.  So, here's the last piece of output:

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2009-02-08 16:33:19 |
+---------------------+
1 row in set (0.03 sec)

mysql> drop procedure if exists `p0`;
Query OK, 0 rows affected (0.03 sec)

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2009-02-08 16:33:19 |
+---------------------+
1 row in set (1 min 17.75 sec)

mysql> create procedure `p0`() select now();
Query OK, 0 rows affected (0.00 sec)

See how "select now()" took > 1 minute to execute !  Show processlist is *not* helpful:

mysql> show processlist;
+----+------+------+------+---------+------+-------+------------------+
| Id | User | Host | db   | Command | Time | State | Info             |
+----+------+------+------+---------+------+-------+------------------+
| 30 | root |      | test | Query   |    0 | NULL  | show processlist |
| 67 | root |      | test | Query   |   34 | NULL  | select now()     |
+----+------+------+------+---------+------+-------+------------------+
2 rows in set (0.02 sec)

If you don't see a problem or have super-fast machine, try with 20000 SPs.
So, either sp cache should be optimized a bit, or some useful diagnostic info can be printed somewhere ...

This means that on a busy system with many SP's, simply creating/dropping an SP can cause problems, due to all queries freezing for a while.

Last of all, full debug binary shows the problem many times worse than release binary.

I believe I pushed a fix for this bug into next-4284. Please re-verify.

Yes, not repeatable with mysql-next-4284

Queued into next-4284 (to be merged into Celosia).

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100216101445-2ofzkh48aq2e0e8o) (version source revid:kostja@sun.com-20091230202224-tmxmnhhvlecoej8w) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100216101208-33qkfwdr0tep3pf2) (version source revid:kostja@sun.com-20091229121905-q27v9932ho9as2ws) (pib:16)

Noted in 6.0.14 changelog.

Purging the stored routine cache could take a long time and render
the server unresponsive.

Setting report to Need Merge pending push of Celosia to release tree.

Pushed into 5.5.3-m3 (revid:alik@sun.com-20100306103849-hha31z2enhh7jwt3) (version source revid:vvaintroub@mysql.com-20100216221947-luyhph0txl2c5tc8) (merge vers: 5.5.99-m3) (pib:16)

Noted in 5.5.3 changelog.

Is there any plan to fix this in 5.1?