Bug #30428 crash from second call of stored procedure
Submitted: 15 Aug 2007 4:28 Modified: 24 Sep 2007 15:22
Reporter: Don Cohen Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:5.0.18-log OS:Linux
Assigned to: CPU Architecture:Any

[15 Aug 2007 4:28] Don Cohen
Description:
I seem to have lucked into a stored procedure that causes a crash on the SECOND call !  Here's the relevant section of the log file.
I'm hoping that this tells you something useful without going into the details of the procedure or the table definitions or the data itself.  I don't think the procedure even writes anything in the DB.
I know you're going to tell me that this is an old version.  I report it anyway in case it might tell you something relevant to newer versions.  Also this is not something I can easily upgrade.  Two reasons for that (1)I'm not the administrator of this system, (2)it's somewhat non standard hardware (sgi).
More details can be obtained if necessary/useful.
The following crash can be easily reproduced on this system by starting the mysql client and calling the stored procedure twice.  I've tried executing the code in the stored procedure and that does not crash (even the second time).

====
070814 21:00:06       4 Query       call StaffViewSkillReadAll(@err,1,1)
070814 21:00:17       4 Query       call StaffViewSkillReadAll(@err,1,1)
mysqld: my_new.cc:51: int __cxa_pure_virtual(): Assertion `"Pure virtual method\
 called." == "Aborted"' failed.
mysqld got signal 6;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=16777216
read_buffer_size=258048
max_used_connections=3
max_connections=100
threads_connected=2
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 92783\
 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Number of processes running now: 0
070814 21:00:17  mysqld restarted
/usr/local/mysql/libexec/mysqld, Version: 5.0.18-log. started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
070814 21:00:17  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.

How to repeat:
see above (description)
[15 Aug 2007 15:15] MySQL Verification Team
Thank you for the bug report. Could you please provide the stored procedure
(and create table if needed) statements?. Thanks in advance.
[16 Aug 2007 3:59] Don Cohen
> Thank you for the bug report. Could you please provide the stored procedure
(and create table if needed) statements?. Thanks in advance.

I'd be interested in what you can deduce from what I sent before, but also in what you can deduce from what I send you now.  In addition to information about the bug I'm interested in ways to avoid it in the short term, e.g., small changes to queries that might make a difference.

Unfortunately the procedure is not small:
create procedure StaffViewSkillReadAll (out err varchar(250),
    in rid integer, in sid integer)
 blk: begin
 select checkPermission("readAssessments") into err;
 if err != "" then leave blk; end if;
 if !(rid=roleFromStaff(sid)) then
    set err = "roleid does not match staffid"; leave blk; end if;
 if higherLorc(rid)=0 then
    set err = "user role lorc not greater than that of subject";
    leave blk; end if;
 SELECT LEO_Capabilities.ID as id,
  LEO_Capabilities.Skills, -- the short description of the capability
  Skillsubcategory, SkillCategory,
  ProficiencyRequiredid, ProficiencyRequired, -- for the role
  LEO_CapabilityRequiredProficiencyLookup.description
  ,LEO_RoleCapabilities.id as rolecapid
  ,LEO_StaffCapabilityRatings.id as staffcapid
  , LEO_StaffCapabilityRatings.skillEffectivenessid,
    LEO_StaffCapabilityRatings.DateTime,
   concat(firstname, " ", lastname) as Ratername,
   LEO_StaffCapabilityRatings.comments
 FROM LEO_Capabilities join
      LEO_CapabilityCategoryXref
      join LEO_CapabilityCategory
      join LEO_Capabilitysubcategory
      join LEO_RoleCapabilities
      join LEO_CapabilityRequiredProficiencyLookup
    left join LEO_StaffCapabilityRatings
    left join LEO_Staff on LEO_StaffCapabilityRatings.rater=LEO_Staff.id
   on LEO_StaffCapabilityRatings.RoleSkillID=LEO_RoleCapabilities.id
 where LEO_Capabilities.SkillcategoryxrefID=LEO_CapabilityCategoryXref.id
 and LEO_CapabilityCategoryXref.SkillsubCategoryid=LEO_Capabilitysubcategory.id
 and LEO_CapabilityCategoryXref.SkillCategoryid=LEO_CapabilityCategory.id
 and LEO_Capabilities.id =LEO_RoleCapabilities.skillid
 and ProficiencyRequiredid=LEO_CapabilityRequiredProficiencyLookup.id
 and LEO_RoleCapabilities.roleid = rid
 order by id, datetime desc;
 end
 $

The functions checkpermission, rolefromstaff, higherlorc are pretty small but are used in a lot of other places and so far this seems to be the only one crashing, so I expect the problem will be in the big query.
All of the tables are innodb.  I'm hoping that the details of their definition isn't as important as this:
[Your comment is too long. Please attach larger files to the bug on the Files tab.  ==> see next msg]

Two more interesting data points.
If I install the definition above into another older database I get the crash from running it twice - meaning this is not related to any recently added data.  In fact the query returns no rows in that database.
Second, if I define the same procedure without the large query, there's no crash.  So the crash clearly has something to do with the large query.
[16 Aug 2007 3:59] Don Cohen
mysql> explain  SELECT LEO_Capabilities.ID as id, 
  LEO_Capabilities.Skills, -- the short description of the capability           
  Skillsubcategory, SkillCategory,                                              
  ProficiencyRequiredid, ProficiencyRequired, -- for the role                   
  LEO_CapabilityRequiredProficiencyLookup.description                           
  ,LEO_RoleCapabilities.id as rolecapid                                         
  ,LEO_StaffCapabilityRatings.id as staffcapid                                  
  , LEO_StaffCapabilityRatings.skillEffectivenessid,                            
    LEO_StaffCapabilityRatings.DateTime,                                        
   concat(firstname, " ", lastname) as Ratername,                               
   LEO_StaffCapabilityRatings.comments                                          
 FROM LEO_Capabilities join                                                     
      LEO_CapabilityCategoryXref                                                
      join LEO_CapabilityCategory                                               
      join LEO_Capabilitysubcategory                                            
      join LEO_RoleCapabilities                                                 
      join LEO_CapabilityRequiredProficiencyLookup                              
    left join LEO_StaffCapabilityRatings                                        
    left join LEO_Staff on LEO_StaffCapabilityRatings.rater=LEO_Staff.id        
   on LEO_StaffCapabilityRatings.RoleSkillID=LEO_RoleCapabilities.id            
 where LEO_Capabilities.SkillcategoryxrefID=LEO_CapabilityCategoryXref.id       
 and LEO_CapabilityCategoryXref.SkillsubCategoryid=LEO_Capabilitysubcategory.id
 and LEO_CapabilityCategoryXref.SkillCategoryid=LEO_CapabilityCategory.id       
 and LEO_Capabilities.id =LEO_RoleCapabilities.skillid                          
 and ProficiencyRequiredid=LEO_CapabilityRequiredProficiencyLookup.id           
 and LEO_RoleCapabilities.roleid = 1                                            
 order by id, datetime desc;
    ->     ->     ->     ->     ->     ->     ->     ->     ->     ->     ->   \
  ->     ->     ->     ->     ->     ->     ->     ->     ->     ->     ->     \
->     ->     ->     -> ERROR 2006 (HY000): MySQL server has gone away
^GNo connection. Trying to reconnect...
Connection id:    145
Current database: devel

+----+-------------+-----------------------------------------+--------+--------\
-----------------------------------------------------------------+---------+---\
------+-----------------------------------------------------+------+-----------\
-----------------------------------+
| id | select_type | table                                   | type   | possibl\
e_keys                                                           | key     | ke\
y_len | ref                                                 | rows | Extra     \
                                   |
+----+-------------+-----------------------------------------+--------+--------\
-----------------------------------------------------------------+---------+---\
------+-----------------------------------------------------+------+-----------\
-----------------------------------+
|  1 | SIMPLE      | LEO_RoleCapabilities                    | ref    | _Profic\
iencyRequiredID,_roleid,_skillid,roleid                          | roleid  | 5 \
      | const                                               |   17 | Using wher\
e; Using temporary; Using filesort |
|  1 | SIMPLE      | LEO_StaffCapabilityRatings              | ALL    | NULL   \
                                                                 | NULL    | NU\
LL    | NULL                                                |   17 |           \
                                   |
|  1 | SIMPLE      | LEO_Staff                               | eq_ref | PRIMARY\
,_ID                                                             | PRIMARY | 4 \
      | devel.LEO_StaffCapabilityRatings.rater              |    1 |           \
                                   |
|  1 | SIMPLE      | LEO_CapabilityRequiredProficiencyLookup | eq_ref | PRIMARY\
,_id                                                             | PRIMARY | 4 \
      | devel.LEO_RoleCapabilities.ProficiencyRequiredID    |    1 |           \
                                   |
|  1 | SIMPLE      | LEO_Capabilities                        | eq_ref | PRIMARY\
,_id,_SkillsubcategoryID                                         | PRIMARY | 4 \
      | devel.LEO_RoleCapabilities.skillid                  |    1 |           \
                                   |
|  1 | SIMPLE      | LEO_CapabilityCategoryXref              | eq_ref | PRIMARY\
,_id,_LEO_SkillsubcategoryLEO_SkillCategoryXref,_SkillCategoryid | PRIMARY | 4 \
      | devel.LEO_Capabilities.SkillcategoryxrefID          |    1 |           \
                                   |
|  1 | SIMPLE      | LEO_Capabilitysubcategory               | eq_ref | PRIMARY\
,_id                                                             | PRIMARY | 4 \
      | devel.LEO_CapabilityCategoryXref.SkillsubCategoryid |    1 |           \
                                   |
|  1 | SIMPLE      | LEO_CapabilityCategory                  | eq_ref | PRIMARY\
                                                                 | PRIMARY | 4 \
      | devel.LEO_CapabilityCategoryXref.SkillCategoryid    |    1 |           \
                                   |
+----+-------------+-----------------------------------------+--------+--------\
-----------------------------------------------------------------+---------+---\
------+-----------------------------------------------------+------+-----------\
-----------------------------------+
8 rows in set (0.04 sec)

I hope the query is handled the same way in and out of a stored procedure?
On the other hand, as already noted, the query doesn't crash when repeated outside the stored procedure.
[27 Aug 2007 5:17] Valeriy Kravchuk
Try to repeat with a newer version, 5.0.45, and inform about the results. In case of the same crash, please, send your my.cnf file content, the results of:

uname -a
ulimit -a

and check if there is a stack trace in the error log.
[27 Aug 2007 22:00] Don Cohen
>Try to repeat with a newer version, 5.0.45, and inform about the results. 
I don't think I can do that on the same machine.
I'll see what can be done.
In the mean while will try on some other machines.
[28 Aug 2007 8:31] Valeriy Kravchuk
Please, do, and inform about the results.
[31 Aug 2007 0:08] Don Cohen
I managed to simplify the procedure until I found what appears to be the problem.
===
create procedure test7 () SELECT LEO_Capabilities.ID as id                       
 FROM LEO_Capabilities join                                                      
      LEO_CapabilityCategoryXref                                                 
      join LEO_CapabilityCategory                                                
      join LEO_Capabilitysubcategory                                             
      join LEO_RoleCapabilities                                                  
      join LEO_CapabilityRequiredProficiencyLookup                               
    left join LEO_StaffCapabilityRatings                                         
    left join LEO_Staff on LEO_StaffCapabilityRatings.rater=LEO_Staff.id         
   on LEO_StaffCapabilityRatings.RoleSkillID=LEO_RoleCapabilities.id             
 ;$
mysql>     ->     ->     ->     ->     ->     ->     ->     ->     ->     -> Que\
ry OK, 0 rows affected (0.00 sec)

mysql> call test7()$
Empty set (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

mysql> call test7()$
Empty set (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

mysql> call test6()$
Empty set (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

mysql> call test6()$
ERROR 2013 (HY000): Lost connection to MySQL server during query
===
If I reverse the order of the last two lines:
    left join LEO_StaffCapabilityRatings                                         
   on LEO_StaffCapabilityRatings.RoleSkillID=LEO_RoleCapabilities.id             
    left join LEO_Staff on LEO_StaffCapabilityRatings.rater=LEO_Staff.id         
then it does not crash.
I hope this gives you an idea of what the probem is (or was in 5.0.18).
[23 Sep 2007 12:21] Valeriy Kravchuk
If you can reproduce the problem on 5.0.45, please, send the EXPLAIN results for "crashing" and "non-crashing" SELECT, and the appropriate part of the error log (you should have a stack trace there).
[24 Sep 2007 3:35] Don Cohen
I've just tried this in my newly built .45
I don't get to try a second time cause the first time goes into an infinite loop, or at least so it seems.  Here's the transcript. 
====
dcohen@saturn:~> mysql --user=root --password="..." --port=3307 --protocol=tcp
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 17 to server version: 5.0.45-log

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

mysql> show databases
show databases
    -> ;
;
+--------------------+
| Database           |
+--------------------+
| information_schema |
| devel              |
| mysql              |
| test               |
+--------------------+
4 rows in set (0.00 sec)

mysql> use devel
Database changed
mysql> delimiter $
delimiter $
mysql> create procedure test7 () SELECT LEO_Capabilities.ID as id                
 FROM LEO_Capabilities join                                                      
      LEO_CapabilityCategoryXref                                                 
      join LEO_CapabilityCategory                                                
      join LEO_Capabilitysubcategory                                             
      join LEO_RoleCapabilities                                                  
      join LEO_CapabilityRequiredProficiencyLookup                               
    left join LEO_StaffCapabilityRatings                                         
    left join LEO_Staff on LEO_StaffCapabilityRatings.rater=LEO_Staff.id         
   on LEO_StaffCapabilityRatings.RoleSkillID=LEO_RoleCapabilities.id             
 ;$
Query OK, 0 rows affected (0.04 sec)

mysql>  call test7()$ 
[[here it ran until I killed it ]]

^C^C

Aborted
dcohen@saturn:~> dcohen@saturn:~> 
====
In fact, I now find that just entering the query without calling the procedure has the same effect!

Here's the explain of the same query:
+----+-------------+-----------------------------------------+--------+---------------+--------------+---------+----------------------------------------+------+-------------+
| id | select_type | table                                   | type   | possible_keys | key          | key_len | ref                                    | rows | Extra       |
+----+-------------+-----------------------------------------+--------+---------------+--------------+---------+----------------------------------------+------+-------------+
|  1 | SIMPLE      | LEO_RoleCapabilities                    | index  | NULL          | PRIMARY      | 4       | NULL                                   |    1 | Using index |
|  1 | SIMPLE      | LEO_StaffCapabilityRatings              | ref    | _RoleSkillID  | _RoleSkillID | 5       | devel.LEO_RoleCapabilities.id          |    1 |             |
|  1 | SIMPLE      | LEO_Staff                               | eq_ref | PRIMARY,_ID   | PRIMARY      | 4       | devel.LEO_StaffCapabilityRatings.rater |    1 | Using index |
|  1 | SIMPLE      | LEO_CapabilityRequiredProficiencyLookup | index  | NULL          | PRIMARY      | 4       | NULL                                   |   16 | Using index |
|  1 | SIMPLE      | LEO_Capabilitysubcategory               | index  | NULL          | PRIMARY      | 4       | NULL                                   |   46 | Using index |
|  1 | SIMPLE      | LEO_CapabilityCategory                  | index  | NULL          | PRIMARY      | 4       | NULL                                   |    3 | Using index |
|  1 | SIMPLE      | LEO_CapabilityCategoryXref              | index  | NULL          | PRIMARY      | 4       | NULL                                   |  138 | Using index |
|  1 | SIMPLE      | LEO_Capabilities                        | index  | NULL          | PRIMARY      | 4       | NULL                                   | 1441 | Using index |
+----+-------------+-----------------------------------------+--------+---------------+--------------+---------+----------------------------------------+------+-------------+
8 rows in set (0.01 sec)
[24 Sep 2007 8:07] Don Cohen
It now occurs to me that the reason for never returning could just be that the query has waaaay too many answers.  When I add "limit 6" to the end of it then I get back a result, and in fact also get back a result the second time, in either version of the query.  Is it the case that the limit does not affect the algorithm other than early termination?  If so, I suspect that the problem is fixed in .45.
...
Even better evidence that the problem is fixed - I copy the original procedure from the original bug report (change the name) and run it in the new database without problem.
[24 Sep 2007 15:22] Valeriy Kravchuk
So, this is not a bug, in 5.0.45 at least.