Bug #43470 Repeated procedure calls on same thread hangs thread
Submitted: 6 Mar 2009 23:58 Modified: 30 Apr 2012 12:49
Reporter: Van Stokes Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:6.0.9-alpha OS:Windows (XP64)
Assigned to: Assigned Account CPU Architecture:Any
Tags: CALL, hang, PROCEDURE, regression, Repeated, stall, thread

[6 Mar 2009 23:58] Van Stokes
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.
[7 Mar 2009 0:37] Van Stokes
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.
[9 Mar 2009 6:35] Van Stokes
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.
[10 Mar 2009 19:23] MySQL Verification Team
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.
[10 Mar 2009 21:26] MySQL Verification Team
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>
[10 Mar 2009 21:27] MySQL Verification Team
Error log

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

[10 Mar 2009 21:29] MySQL Verification Team
See bug: http://bugs.mysql.com/bug.php?id=20090.
[11 Mar 2009 9:57] Van Stokes
Hung SELECT processes before and after kill.

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

[11 Mar 2009 10:15] Van Stokes
Print Screen of Task Manager showing mysqld CPU usage.

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

[11 Mar 2009 10:20] Van Stokes
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.
[12 Mar 2009 13:40] MySQL Verification Team
Not repeatable on 5.1 version.
[31 May 2009 22:08] Van Stokes
Upgraded from MySQL 6.0.10-alpha to MySQL 6.0.11-alpha. 
No performance improvement in the query.
[30 Apr 2012 12:49] MySQL Verification Team
Since 6.0.9 is not a valid version anymore, and the symptoms are closely resembling known bugs, I'll say this is a duplicate.

Bug 11745800 - 20090: INNODB: ERROR: TRYING TO DECLARE TRX TO ENTER INNODB
Bug 11746321 - 25439: TRX->ACTIVE_TRANS == 0, BUT TRX->CONC_STATE != TRX_NOT_STARTED
http://bugs.mysql.com/bug.php?id=54475 (improper error handling causes cascading crashing failures in innodb/ndb)