MySQL Bugs: #43470: Repeated procedure calls on same thread hangs thread

Bug #43470	Repeated procedure calls on same thread hangs thread
Submitted:	7 Mar 0:58	Modified:	18 Sep 0:03
Reporter:	Van Stokes
Status:	Open
Category:	Server: InnoDB	Severity:	S1 (Critical)
Version:	6.0.9-alpha	OS:	Microsoft Windows (XP64)
Assigned to:	Calvin Sun	Target Version:
Tags:	regression, thread, stall, hang, PROCEDURE, CALL, Repeated
Triage:	Triaged: D2 (Serious)

Description:
We found that a repeated procedure call via the same thread to a stored procedure having
multiple result sets hangs the thread indefinitely (until killed by admin).

Our server application code calls a sql stored procedure about a dozen times via a
for/next loop. The parameters passed to the store procedure are different. In the first
pass the procedure works as expected and four result sets are returned (some or all
result sets may be empty). However, on the second pass the thread hangs. This is visible
in the process list and the "SELECT" statement is visible in the "INFO" column.

This procedure works fine in the 5.1.3x version of MySQL. We were using the C API from
5.1.30. We upgraded the API to 6.0.9-alpha to ensure it wasn't an API issue.

We started the MySQL Query Browser and ran the sql procedure manually. The first call
worked fine however the second call hung the thread.

How to repeat:
1. Start MySQL Query Browser.
2. CALL FactionListServices( 2, 6, 551014 );  -- Works, four result sets returned
3. CALL FactionListServices( 2, 6, 551022 );  -- Hangs

Suggested fix:
Not sure. Perhaps the previous call was not released by the server or the server believes
the results are the same.

We also noticed another issue. If we kill these "hung" threads (using MySQL Administrator
1.12.17) the process/thread is labeled "killed" but is never removed from the process
table. Furthermore, "mysqld" pegs the CPU at 99%. "mysqld" runs fine (normal CPU usage)
but when we try to kill one of these hung processes the CPU utilization pegs.

There is a definitely an issue with stored procedures running SELECT queries. We found
more threads hung performing a SELECT. What seems to be a common denominator is that the
SELECT statement is using a VIEW and either has WHERE IN or DISTINCT (or both) operands
in the statement.

These hung threads consume large amounts of CPU time.

Thank you for the bug report. Testing today source server on Windows I got:

c:\dbs>c:\dbs\6.0\bin\mysql -uroot --port=3600 --prompt="mysql 6.0 > "
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 11
Server version: 6.0.10-alpha-Win x86-64 bzr revno:3036-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql 6.0 > show processlist;
+----+------+-----------------+------+---------+------+-------+------------------+
| Id | User | Host            | db   | Command | Time | State | Info             |
+----+------+-----------------+------+---------+------+-------+------------------+
| 11 | root | localhost:53922 | NULL | Query   |    0 | NULL  | show processlist |
+----+------+-----------------+------+---------+------+-------+------------------+
1 row in set (0.00 sec)

Now launch Query Browser and do the first call:

mysql 6.0 > show processlist;
+----+------+-----------------+---------+---------+------+-------+------------------+
| Id | User | Host            | db      | Command | Time | State | Info             |
+----+------+-----------------+---------+---------+------+-------+------------------+
| 11 | root | localhost:53922 | NULL    | Query   |    0 | NULL  | show processlist |
| 12 | root | localhost:53924 | origins | Sleep   |   37 | NULL  | NULL             |
| 14 | root | localhost:53926 | origins | Sleep   |   13 | NULL  | NULL             |
| 15 | root | localhost:53927 | NULL    | Sleep   |    3 | NULL  | NULL             |
+----+------+-----------------+---------+---------+------+-------+------------------+
4 rows in set (0.00 sec)

QB returned 7 rows.

Do 2nd call:

mysql 6.0 > show processlist;
+----+------+-----------------+---------+---------+------+-------+------------------+
| Id | User | Host            | db      | Command | Time | State | Info             |
+----+------+-----------------+---------+---------+------+-------+------------------+
| 11 | root | localhost:53922 | NULL    | Query   |    0 | NULL  | show processlist |
| 12 | root | localhost:53924 | origins | Sleep   |  129 | NULL  | NULL             |
| 14 | root | localhost:53926 | origins | Sleep   |    8 | NULL  | NULL             |
| 15 | root | localhost:53927 | NULL    | Sleep   |    0 | NULL  | NULL             |
+----+------+-----------------+---------+---------+------+-------+------------------+
4 rows in set (0.00 sec)

QB returned 10 rows.

Now quit QB:

mysql 6.0 > show processlist;
+----+------+-----------------+------+---------+------+-------+------------------+
| Id | User | Host            | db   | Command | Time | State | Info             |
+----+------+-----------------+------+---------+------+-------+------------------+
| 11 | root | localhost:53922 | NULL | Query   |    0 | NULL  | show processlist |
+----+------+-----------------+------+---------+------+-------+------------------+
1 row in set (0.00 sec)

mysql 6.0 >

The above behavior happens because QB does a connection for every query and mysql client
doesn't. So I wasn't able to see a select hanging in the current source server.

Sorry don't need feedback I didn't noticed the below error message from InnoDB displayed
for every call to the procedure disregarding if perfomed by QB or mysql client:

c:\dbs>c:\dbs\6.0\bin\mysqld --defaults-file=c:\dbs\6.0\my.ini --standalone --console
090310 18:16:45  InnoDB: Started; log sequence number 0 674811651
090310 18:16:45 [Note] Event Scheduler: Loaded 0 events
090310 18:16:45 [Note] c:\dbs\6.0\bin\mysqld: ready for connections.
Version: '6.0.10-alpha-Win x86-64 bzr revno:3036-log'  socket: ''  port: 3600  Source
distribution
090310 18:17:34  InnoDB: Error: trying to declare trx to enter InnoDB, but
InnoDB: it already is declared.
TRANSACTION 0 1514753, ACTIVE 0 sec, OS thread id 828 starting index read, thread
declared inside InnoDB 0
mysql tables in use 8, locked 1
MySQL thread id 1, query id 25 localhost ::1 root Copying to tmp table
SELECT Zone_View.*

<cut>

Error log

Attachment: innodb-error.txt (text/plain), 7.77 KiB.

See bug: http://bugs.mysql.com/bug.php?id=20090.

Hung SELECT processes before and after kill.

Attachment: Bug43470-HungProcesses.txt (text/plain), 12.74 KiB.

Print Screen of Task Manager showing mysqld CPU usage.

Attachment: mysql-cpu-usage.PNG (image/png, text), 29.70 KiB.

I just added a couple of files to show what is happening from our point of view. We tried
to kill off the hung processes but as you can see they get labeled as KILLED but never go
away. Also included a print screen of the CPU usage of mysqld.

The only known solution that we know to work is to KILL the mysqld process via the TASK
MANAGER. We can not do a normal shutdown as the server will not respond to it.

Not repeatable on 5.1 version.

Upgraded from MySQL 6.0.10-alpha to MySQL 6.0.11-alpha. 
No performance improvement in the query.