| Bug #45259 | 2 stored procedures caused crashes of the mysqld process in 5.1.x | ||
|---|---|---|---|
| Submitted: | 2 Jun 2009 10:06 | Modified: | 4 Jun 2009 9:36 |
| Reporter: | Anthony Mann | Email Updates: | |
| Status: | Can't repeat | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S2 (Serious) |
| Version: | 5.1.34 | OS: | Windows (Server 2003) |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | assertion failure, crash, stored procedure, Windows Server 2003 | ||
[2 Jun 2009 10:15]
MySQL Verification Team
Antony, if you comment out innodb_locks_unsafe_for_binlog in my.ini and never use read committed transaction isolation level does it still crash ? could be bug #39320
[2 Jun 2009 10:37]
Anthony Mann
Antony, if you comment out innodb_locks_unsafe_for_binlog in my.ini -- This is not currently set in the my.ini file (see file now attached) Thank you for the quick response
[2 Jun 2009 11:04]
Anthony Mann
my.ini
Attachment: my.ini (application/octet-stream, text), 8.82 KiB.
[2 Jun 2009 11:12]
MySQL Verification Team
Thank you for the feedback. Could you please provide the complete test case (create table, data, procedure, procedure query which crash, etc) to test against the current source server, looks like the same case as bug commented by Shane and the fix will be applied in the next release 5.1.35. Thanks in advance.
[2 Jun 2009 12:35]
Anthony Mann
data submitted
[3 Jun 2009 19:40]
MySQL Verification Team
Thank you for the feedback. I couldn't repeat with current source server: mysql 5.1 >CALL SP_GetAccessLevelByID(1); +---------+ | Level | +---------+ | module1 | +---------+ 1 row in set (0.10 sec) Query OK, 0 rows affected (0.11 sec) mysql 5.1 >show variables like "%version%"; +-------------------------+---------------------+ | Variable_name | Value | +-------------------------+---------------------+ | protocol_version | 10 | | version | 5.1.36-Win X64-log | | version_comment | Source distribution | | version_compile_machine | unknown | | version_compile_os | Win64 | +-------------------------+---------------------+ 5 rows in set (0.00 sec) mysql 5.1 >
[4 Jun 2009 9:30]
Anthony Mann
Hi there, i have just re-installed SQL version 5.1.34 on our test machine (osx 10.4 - powerpc 64bit) which also had the same issue as our windows server when tested. Here is a dump of the entire query log string leading up to the crash. 090604 10:19:35 24 Query SELECT tbl_users.userID, tbl_users.userPassedTest, tbl_users.userUsername, tbl_users.TitleID, tbl_titles.titleName AS userTitle, tbl_users.userFirstname, tbl_users.userSurname, tbl_users.userTel, tbl_users.userEmail, tbl_users.PracticeID, tbl_users.userDOB, tbl_users.userHide, tbl_users.userDefaultTerritory, tbl_users.userLastActive, tbl_users.userLastUpdated, tbl_users.userUpdatedBy, tbl_users.userSeenRegConfirm, tbl_users.userMovedToNonAR FROM tbl_users LEFT JOIN tbl_titles ON tbl_users.TitleID= tbl_titles.titleID WHERE tbl_users.userEmail = 'testing@redantsolutions.com' AND tbl_users.userPassword = 'passwo' AND userEnabled = 1 AND userHide = 0 AND userRetestIncomplete = 0 24 Query SELECT tbl_join_userroles.RoleID AS RoleID, tbl_roles.roleName AS roleName FROM tbl_join_userroles, tbl_roles WHERE tbl_join_userroles.UserID = 1 AND tbl_roles.roleID = tbl_join_userroles.RoleID 24 Query USE `piawgreen` 24 Query SELECT DATABASE() 24 Query USE `piawgreen` 24 Query SHOW CREATE PROCEDURE `piawgreen`.`SP_GetAccessLevelByID` 24 Query CALL SP_GetAccessLevelByID(1) /usr/local/mysql/bin/mysqld, Version: 5.1.34-log (MySQL Community Server (GPL)). started with: Tcp port: 0 Unix socket: (null) Time Id Command Argument if necessary i can provide you with remote access to the machine itself. Let me know if there is anything i can do to provide more information.
[4 Jun 2009 9:36]
Anthony Mann
the version of mySQL used in the previous dump was: 5.1.34 osx10.4 powerpc 64bit
[4 Jun 2009 9:44]
Sveta Smirnova
Thank you for the feedback. Stack trace looks similar to bug #39320 which is fixed in version 5.1.35. Please wait next release, upgrade, try in your environment and reopen bug if the problem still exists.
Description: A critical error in InnoDB when certain aspects of a stored procedure are processed: 090602 9:30:59 InnoDB: Assertion failure in thread 2464 in file .\btr\btr0pcur .c line 217 Full dump of error: 090602 9:30:10 InnoDB: Started; log sequence number 0 3563088536 090602 9:30:10 [Note] Event Scheduler: Loaded 0 events 090602 9:30:10 [Note] mysqld: ready for connections. Version: '5.1.34-community' socket: '' port: 3306 MySQL Community Server (GPL ) len 112; hex 801289166e59ec1600000000000000000300000002000000000000000000000001 00000000000000000000000000000000000000000000000100000083445107000000000000000000 00000000000000000000000000000060e1117704000000808c8916000000000000000000000000; asc nY DQ ` w ;TRANSACTION 0 916228, ACTIVE 0 sec, OS thre ad id 2464 unlock_row, thread declared inside InnoDB 500 mysql tables in use 1, locked 1 3 lock struct(s), heap size 1024, 1 row lock(s) MySQL thread id 2, query id 27 localhost 127.0.0.1 root Sorting result CALL SP_GetAccessLevelByID(1) 090602 9:30:59 InnoDB: Assertion failure in thread 2464 in file .\btr\btr0pcur .c line 217 InnoDB: We intentionally generate a memory trap. InnoDB: Submit a detailed bug report to http://bugs.mysql.com. InnoDB: If you get repeated assertion failures or crashes, even InnoDB: immediately after the mysqld startup, there may be InnoDB: corruption in the InnoDB tablespace. Please refer to InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html InnoDB: about forcing recovery. 090602 9:30:59 - mysqld got exception 0xc0000005 ; 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=268435456 read_buffer_size=65536 max_used_connections=2 max_threads=800 threads_connected=2 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 727994 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. thd: 0x379c5630 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... 007009C2 mysqld.exe!btr_pcur_restore_position()[btr0pcur.c:217] 006B4E0A mysqld.exe!row_unlock_for_mysql()[row0mysql.c:1543] 006A9826 mysqld.exe!ha_innobase::unlock_row()[ha_innodb.cc:4154] 00439822 mysqld.exe!find_all_keys()[filesort.cc:621] 00439E37 mysqld.exe!filesort()[filesort.cc:245] 005829F7 mysqld.exe!create_sort_index()[sql_select.cc:13456] 0058F843 mysqld.exe!JOIN::exec()[sql_select.cc:2148] 00496E67 mysqld.exe!subselect_single_select_engine::exec()[item_subselect.cc: 1961] 00495E7D mysqld.exe!Item_subselect::exec()[item_subselect.cc:265] 0049662D mysqld.exe!Item_exists_subselect::val_bool()[item_subselect.cc:777] 0050200B mysqld.exe!sp_instr_jump_if_not::exec_core()[sp_head.cc:3108] 0050481A mysqld.exe!sp_lex_keeper::reset_lex_and_exec_core()[sp_head.cc:2732] 00504B75 mysqld.exe!sp_instr_jump_if_not::execute()[sp_head.cc:3091] 00505E30 mysqld.exe!sp_head::execute()[sp_head.cc:1252] 00506F78 mysqld.exe!sp_head::execute_procedure()[sp_head.cc:1981] 00557D51 mysqld.exe!mysql_execute_command()[sql_parse.cc:4328] 0055A133 mysqld.exe!mysql_parse()[sql_parse.cc:5906] 0055AC23 mysqld.exe!dispatch_command()[sql_parse.cc:1218] 0055BA27 mysqld.exe!do_command()[sql_parse.cc:861] 005DEC81 mysqld.exe!handle_one_connection()[sql_connect.cc:1115] 00644D1B mysqld.exe!pthread_start()[my_winthread.c:85] 0072A1A3 mysqld.exe!_callthreadstart()[thread.c:293] FC8FE900 Trying to get some variables. Some pointers may be invalid and cause the dump to abort... thd->query at 379D1028=CALL SP_GetAccessLevelByID(1) thd->thread_id=2 thd->killed=NOT_KILLED The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains information that should help you find out what is causing the crash. C:\Program Files\MySQL\MySQL Server 5.1\bin>mysqld --console 090602 9:31:01 [Warning] Changed limits: max_open_files: 2048 max_connections: 800 table_cache: 619 InnoDB: The log sequence number in ibdata files does not match InnoDB: the log sequence number in the ib_logfiles! 090602 9:31:02 InnoDB: Database was not shut down normally! InnoDB: Starting crash recovery. InnoDB: Reading tablespace information from the .ibd files... InnoDB: Restoring possible half-written data pages from the doublewrite InnoDB: buffer... 090602 9:31:03 InnoDB: Started; log sequence number 0 3563088588 090602 9:31:03 [Note] Event Scheduler: Loaded 0 events 090602 9:31:03 [Note] mysqld: ready for connections. Version: '5.1.34-community' socket: '' port: 3306 MySQL Community Server (GPL Stored Procedure: BEGIN DECLARE iSalesLevel INT; DECLARE iMinSales INT; DECLARE iNextLevel INT; DECLARE iModulePassed INT; DECLARE iPracticeGroup varchar(255) DEFAULT ''; IF EXISTS (SELECT tbl_tests.ModuleID FROM tbl_tests WHERE tbl_tests.userid = userid AND tbl_tests.testPassed = 1 AND tbl_tests.testIsRetest = 0 ORDER BY moduleID DESC LIMIT 0,1 ) THEN SET iModulePassed = (SELECT tbl_tests.ModuleID FROM tbl_tests WHERE tbl_tests.userid = userid AND tbl_tests.testPassed = 1 AND tbl_tests.testIsRetest = 0 ORDER BY moduleID DESC LIMIT 0,1 ); END IF; If Exists(SELECT practiceBusinessGroupName FROM tbl_practices INNER JOIN tbl_users ON tbl_users.practiceID = tbl_practices.practiceID WHERE tbl_users.userID = userid) THEN SET iPracticeGroup = ( SELECT practiceBusinessGroupName FROM tbl_practices INNER JOIN tbl_users ON tbl_users.practiceID = tbl_practices.practiceID WHERE tbl_users.userID = userid ); END IF; IF iPracticeGroup = '' OR iPracticeGroup IS NULL THEN SET iSalesLevel = ( SELECT practiceSales FROM tbl_practices INNER JOIN tbl_users ON tbl_users.practiceID = tbl_practices.practiceID WHERE tbl_users.userID = userid ); ELSE SET iSalesLevel = ( SELECT SUM(practiceSales) FROM tbl_practices WHERE practiceBusinessGroupName = iPracticeGroup ); END IF; IF iModulePassed > 0 THEN IF iModulePassed < 4 THEN SET iNextLevel = iModulePassed +1; END IF; SET iMinSales = ( SELECT moduleaccesslevelMinSalesLevel AS Level FROM tbl_moduleaccesslevels WHERE moduleaccesslevelName = CONCAT('module',iNextLevel) ); IF iMinSales <= iSalesLevel THEN SELECT CONCAT('module',iNextLevel) AS Level; #SELECT CONCAT(CONCAT(CONCAT(CONCAT(CONCAT(CONCAT(CONCAT(CONCAT('module',iNextLevel),' saleslevel '),iSalesLevel), ' minsales '), iMinSales), ' iModulePassed '),iModulePassed),CONCAT('module',iModulePassed)) AS Level;# ELSE SELECT moduleaccesslevelName AS Level FROM tbl_moduleaccesslevels WHERE moduleaccesslevelMinSalesLevel <= iSalesLevel ORDER BY moduleaccesslevelName DESC LIMIT 0,1; END IF; ELSE SELECT ("module1") AS Level; END IF; END To remedy the problem we have rolled back to 5.0 and the issues appear to have vanished. How to repeat: run the stored procedure with valid data on mySQL 5.1.x Suggested fix: unknown...