| Bug #86260 | Assert on KILL'ing a stored routine invocation | ||
|---|---|---|---|
| Submitted: | 10 May 2017 6:47 | Modified: | 17 Jan 2018 17:00 |
| Reporter: | Laurynas Biveinis (OCA) | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Stored Routines | Severity: | S2 (Serious) |
| Version: | 5.6.36 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | KILL, regression, stored routines | ||
[10 May 2017 6:48]
Laurynas Biveinis
This appears to be a regression introduced by
commit d7b37d4d141a95f577916448650c429f0d6e193d
Author: Sreeharsha Ramanavarapu <sreeharsha.ramanavarapu@oracle.com>
Date: Wed Feb 22 11:02:07 2017 +0530
Bug #25053286: USE VIEW WITH CONDITION IN PROCEDURE CAUSES
INCORRECT BEHAVIOR
Issue:
------
This problem occurs when a stored procedure contains a
query with a view. While resolving the columns in the
WHERE condition, find_field_in_view insists on creating a
Item_direct_view_ref object every time an execution
happens. This object is not destroyed at the end of the
execution.
In the next execution, a new object is created and will be
appended to the free_list. Hence the size of the free_list
is growing and the cleanup phase at the end of each execute
takes increasingly longer time.
Solution:
---------
This is a regression due to the fix for BUG#19897405.
Ideally the Item_direct_view_ref object (which is related
to the view's column in WHERE clause) should be created at
the beginning of every execution and destroyed at the end.
This doesn't happen because the check related to the status
(STMT_INITIALIZED_FOR_SP / STMT_EXECUTED) had been removed.
This check has been re-introduced.
Scenario 1 in BUG#19897405:
--------------------------
a) SP is executed--> The view fields are resolved/fixed.
b) FLUSH TABLE <table-name>.
c) SP is executed--> Triggers re-prepare--> Query arena
state is not reset and remains as 'STMT_EXECUTED'.
Previously created Item_direct_view_ref object is
destroyed. The view fields are resolved/fixed
using the execution mem_root. It creates a new
Item_direct_view_ref object, this is destroyed at the
end of the execution.
d) SP is executed--> Server crashes while trying to access
the resolved view columns allocated on the execution
mem_root which was freed after execution(c).
Solution to Scenario 1 in BUG#19897405:
---------------------------------------
The root cause of the problem mentioned in BUG#19897405 is
that when a re-prepare error is raised due to a
FLUSH TABLE / DROP TABLE, the state of statement arena
should be switched to STMT_INITIALIZED_FOR_SP. Without
this, the statement is unaware that previously created
Item_direct_view_ref have been destroyed after the table
re-open. While it creates a new Item_direct_view_ref
object, this is destroyed at the end of the execution.
Hence the execution that follows will not have any
Item_direct_view_ref to use.
The fix here is to set the state to STMT_INITIALIZED_FOR_SP
after the re-prepare error is raised.
Problem 2 in BUG#19897405:
--------------------------
a) SP is executed--> The view fields are resolved/fixed.
b) SP is executed--> Gets re-prepare error. Destroys
Item_direct_view_ref object. At the end "TABLE EXISTS"
error is raised and state is set to EXECUTED
c) DROP TABLE <table-created-in-sp>
d) SP is executed--> Creates new item_direct_view_ref
object. Destroys the object at the end of the statement.
d) DROP TABLE <table-created-in-sp>
e) SP is executed--> Server crashes while trying to
access the resolved view columns allocated on the
execution mem_root which was freed after execution.
Solution to Scenario 2 in BUG#19897405:
---------------------------------------
CREATE TABLE ... SELECT statement in an SP requires some
special handling. The state is always set to
STMT_INITIALIZED_FOR_SP in such a case.
[10 May 2017 7:11]
Roel Van de Paar
Also see bug 76912
[11 May 2017 5:55]
MySQL Verification Team
Hello Laurynas, Thank you for the report and feedback! Thanks, Umesh
[11 May 2017 5:55]
MySQL Verification Team
test results
Attachment: 86260_5.6.36.results (application/octet-stream, text), 164.25 KiB.
[25 May 2017 9:47]
Laurynas Biveinis
Bug 86260 fix for 5.6 (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.
Contribution: bug86260-5.6.patch (application/octet-stream, text), 7.07 KiB.
[25 May 2017 9:48]
Laurynas Biveinis
Bug 86260 fix for 5.7 (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.
Contribution: bug86260-5.7.patch (application/octet-stream, text), 7.09 KiB.
[25 May 2017 9:48]
Laurynas Biveinis
Bug 86260 regression testcase for 8.0.1 (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.
Contribution: bug86260-8.0.1-testcase.patch (application/octet-stream, text), 2.39 KiB.
[25 May 2017 9:49]
Laurynas Biveinis
Submitted fixes for 5.6 and 5.7. The issue did not reproduce under 8.0.1, I haven't researched why, the 8.0.1 patch contains only the testcase.
[17 Jan 2018 17:00]
Paul DuBois
Posted by developer: Fixed in 5.6.40, 5.7.22, 8.0.5, 9.0.0. For debug builds, using KILL to terminate a stored routine could raise an assertion. Thanks to Laurynas Biveinis for the patch.
Description: Killing a stored routine invocation results in a debug assert. Assertion failed: (m_status == DA_ERROR), function sql_errno, file /Users/laurynas/percona/mysql-server/sql/sql_error.h, line 655. 06:41:26 UTC - mysqld got signal 6 ; ... thread #18, stop reason = signal SIGSTOP frame #0: 0x00007fffcb217d42 libsystem_kernel.dylib`__pthread_kill + 10 frame #1: 0x00007fffcb3055bf libsystem_pthread.dylib`pthread_kill + 90 frame #2: 0x0000000102f30fab mysqld-debug`my_write_core(sig=6) at stacktrace.c:424 frame #3: 0x0000000102b919c9 mysqld-debug`::handle_fatal_signal(sig=6) at signal_handler.cc:230 frame #4: 0x00007fffcb2f8b3a libsystem_platform.dylib`_sigtramp + 26 frame #5: 0x00007fffcb217d43 libsystem_kernel.dylib`__pthread_kill + 11 frame #6: 0x00007fffcb3055bf libsystem_pthread.dylib`pthread_kill + 90 frame #7: 0x00007fffcb17d420 libsystem_c.dylib`abort + 129 frame #8: 0x00007fffcb144893 libsystem_c.dylib`__assert_rtn + 320 frame #9: 0x0000000102a08500 mysqld-debug`Diagnostics_area::sql_errno(this=0x00007fce01981b28) const at sql_error.h:655 frame #10: 0x0000000102ba372c mysqld-debug`sp_lex_instr::reset_lex_and_exec_core(this=0x00007fce0087e210, thd=0x00007fce0197ea00, nextp=0x00007000049d0478, open_tables=false) at sp_instr.cc:460 frame #11: 0x0000000102ba41b1 mysqld-debug`sp_lex_instr::validate_lex_and_execute_core(this=0x00007fce0087e210, thd=0x00007fce0197ea00, nextp=0x00007000049d0478, open_tables=false) at sp_instr.cc:688 frame #12: 0x0000000102ba4757 mysqld-debug`sp_instr_stmt::execute(this=0x00007fce0087e210, thd=0x00007fce0197ea00, nextp=0x00007000049d0478) at sp_instr.cc:865 frame #13: 0x0000000102b9ca32 mysqld-debug`sp_head::execute(this=0x00007fce0087c610, thd=0x00007fce0197ea00, merge_da_on_success=true) at sp_head.cc:648 frame #14: 0x0000000102b9e34b mysqld-debug`sp_head::execute_function(this=0x00007fce0087c610, thd=0x00007fce0197ea00, argp=0x8f8f8f8f8f8f8f8f, argcount=0, return_value_fld=0x00007fce019903c8) at sp_head.cc:1094 frame #15: 0x0000000102aad64b mysqld-debug`Item_func_sp::execute_impl(this=0x00007fce0198e8b0, thd=0x00007fce0197ea00) at item_func.cc:6939 frame #16: 0x0000000102aad38a mysqld-debug`Item_func_sp::execute(this=0x00007fce0198e8b0) at item_func.cc:6868 frame #17: 0x0000000102ab1939 mysqld-debug`Item_func_sp::val_int(this=0x00007fce0198e8b0) at item_func.h:2133 frame #18: 0x0000000102a381da mysqld-debug`Item::send(this=0x00007fce0198e8b0, protocol=0x00007fce0197ef68, buffer=0x00007000049d1938) at item.cc:6925 frame #19: 0x0000000102b86827 mysqld-debug`Protocol::send_result_set_row(this=0x00007fce0197ef68, row_items=0x00007fce019810e8) at protocol.cc:844 frame #20: 0x0000000102c2b62a mysqld-debug`select_send::send_data(this=0x00007fce0198ff10, items=0x00007fce019810e8) at sql_class.cc:2541 frame #21: 0x0000000102c4d7b9 mysqld-debug`JOIN::exec(this=0x00007fce0198ff38) at sql_executor.cc:151 frame #22: 0x0000000102d1dfe6 mysqld-debug`mysql_execute_select(thd=0x00007fce0197ea00, select_lex=0x00007fce01980fc8, free_join=true) at sql_select.cc:1101 frame #23: 0x0000000102d1c5f5 mysqld-debug`mysql_select(thd=0x00007fce0197ea00, tables=0x0000000000000000, wild_num=0, fields=0x00007fce019810e8, conds=0x0000000000000000, order=0x00007fce01981190, group=0x00007fce019810c8, having=0x0000000000000000, select_options=2147748608, result=0x00007fce0198ff10, unit=0x00007fce01980980, select_lex=0x00007fce01980fc8) at sql_select.cc:1222 frame #24: 0x0000000102d1c1e9 mysqld-debug`handle_select(thd=0x00007fce0197ea00, result=0x00007fce0198ff10, setup_tables_done_option=0) at sql_select.cc:101 frame #25: 0x0000000102cc593d mysqld-debug`execute_sqlcom_select(thd=0x00007fce0197ea00, all_tables=0x0000000000000000) at sql_parse.cc:5182 frame #26: 0x0000000102cbb2fa mysqld-debug`mysql_execute_command(thd=0x00007fce0197ea00) at sql_parse.cc:2690 frame #27: 0x0000000102cb88e3 mysqld-debug`mysql_parse(thd=0x00007fce0197ea00, rawbuf="SELECT f1()", length=11, parser_state=0x00007000049d5380) at sql_parse.cc:6434 frame #28: 0x0000000102cb51ff mysqld-debug`dispatch_command(command=COM_QUERY, thd=0x00007fce0197ea00, packet="", packet_length=11) at sql_parse.cc:1372 frame #29: 0x0000000102cb7dfb mysqld-debug`do_command(thd=0x00007fce0197ea00) at sql_parse.cc:1039 frame #30: 0x0000000102c3b8e2 mysqld-debug`do_handle_one_connection(thd_arg=0x00007fce0197ea00) at sql_connect.cc:982 frame #31: 0x0000000102c3b68d mysqld-debug`::handle_one_connection(arg=0x00007fce0197ea00) at sql_connect.cc:899 frame #32: 0x000000010330a35d mysqld-debug`::pfs_spawn_thread(arg=0x00007fcdfff54590) at pfs.cc:1860 frame #33: 0x00007fffcb3029af libsystem_pthread.dylib`_pthread_body + 180 frame #34: 0x00007fffcb3028fb libsystem_pthread.dylib`_pthread_start + 286 frame #35: 0x00007fffcb302101 libsystem_pthread.dylib`thread_start + 13 How to repeat: Source code patch for debug sync: diff --git a/sql/sp_instr.cc b/sql/sp_instr.cc index 2de6c99bc56..ea12e9f9b94 100644 --- a/sql/sp_instr.cc +++ b/sql/sp_instr.cc @@ -28,6 +28,7 @@ #include "sql_prepare.h" // reinit_stmt_before_use #include "transaction.h" // trans_commit_stmt #include "sql_audit.h" +#include "debug_sync.h" // DEBUG_SYNC #include <algorithm> @@ -397,6 +398,8 @@ bool sp_lex_instr::reset_lex_and_exec_core(THD *thd, } else { + DEBUG_SYNC(thd, "sp_lex_instr_before_exec_core"); + rc= exec_core(thd, nextp); DBUG_PRINT("info",("exec_core returned: %d", rc)); } MTR testcase: --source include/have_debug_sync.inc --source include/count_sessions.inc CREATE TABLE t1 (a INT); DELIMITER |; CREATE FUNCTION f1() RETURNS INT BEGIN INSERT INTO t1 VALUES (1); RETURN 1; END| DELIMITER ;| --connect(con1,localhost,root) --connection default --let $sp_con_id= `SELECT CONNECTION_ID()` SET DEBUG_SYNC= "sp_lex_instr_before_exec_core SIGNAL sp_ready WAIT_FOR sp_finish"; send SELECT f1(); --connection con1 SET DEBUG_SYNC="now WAIT_FOR sp_ready"; --replace_result $sp_con_id sp_con_id --eval KILL $sp_con_id SET DEBUG_SYNC="now SIGNAL sp_finish"; --connection default reap; disconnect con1; --source include/wait_until_count_sessions.inc