[MDEV-14603] signal 11 with short stacktrace Created: 2017-12-07  Updated: 2020-08-25  Resolved: 2018-01-23

Status: Closed
Project: MariaDB Server
Component/s: Prepared Statements, Stored routines
Affects Version/s: 10.2.11
Fix Version/s: 10.2.13, 10.3.5

Type: Bug Priority: Major
Reporter: Richard Stracke Assignee: Alexander Barkov
Resolution: Fixed Votes: 1
Labels: None
Environment:

Red Hat 7,4

Issue Links:
Relates
relates to MDEV-14657 Crash while trying to find matching c... Closed
relates to MDEV-14949 Crash signal 11 in prepared statement... Closed
relates to MDEV-12060 Crash in EXECUTE IMMEDIATE with an ex... Closed
Sprint: 10.0.34

 Description   

Stacktrace:

2017-12-07 17:00:22 140314162034432 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4062ms. The settings might not be optimal. (flushed=1968 and evicted=0, during the time.)
 
171207 17:00:56 [ERROR] mysqld got signal 11 ;
 
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.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
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.
 
 
 
Server version: 10.2.11-MariaDB-log
 
key_buffer_size=67108864
 
read_buffer_size=131072
 
max_used_connections=28
 
max_threads=302
 
thread_count=29
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 938412 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f9c404435c8
 
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...
 
stack_bottom = 0x7f9de4630d70 thread_stack 0x40000
 
(my_addr_resolve failure: fork)
 
/usr/sbin/mysqld(my_print_stacktrace+0x2e) [0x557ff44a844e]
 
/usr/sbin/mysqld(handle_fatal_signal+0x30d) [0x557ff3f376dd]
 
/lib64/libpthread.so.0(+0xf5e0) [0x7fb2ed1f05e0]



 Comments   
Comment by Richard Stracke [ 2017-12-08 ]

more verbose stacktrace

 
 
Thread pointer: 0x7f6fdc0009a8
 
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...
 
stack_bottom = 0x7f71342a8d70 thread_stack 0x40000
 
(my_addr_resolve failure: fork)
 
/usr/sbin/mysqld(my_print_stacktrace+0x2e) [0x55a4397d444e]
 
/usr/sbin/mysqld(handle_fatal_signal+0x30d) [0x55a4392636dd]
 
/lib64/libpthread.so.0(+0xf5e0) [0x7f86373eb5e0]
 
/lib64/libc.so.6(+0x86d51) [0x7f86359c4d51]
 
/usr/sbin/mysqld(+0xcd6949) [0x55a43981c949]
 
/usr/sbin/mysqld(my_vsnprintf_ex+0x282) [0x55a43981d6e2]
 
/usr/sbin/mysqld(my_snprintf+0x7d) [0x55a43981dc9d]
 
/usr/sbin/mysqld(sp_cache_lookup(sp_cache**, Database_qualified_name const*)+0x53) [0x55a439020503]
 
/usr/sbin/mysqld(Sp_handler::sp_find_package_routine(THD*, st_mysql_const_lex_string, Database_qualified_name const*, bool) const+0x48) [0x55a43938a598]
 
/usr/sbin/mysqld(Sp_handler_package_procedure::sp_find_routine(THD*, Database_qualified_name const*, bool) const+0xb5) [0x55a43938a755]
 
/usr/sbin/mysqld(+0x55c1eb) [0x55a4390a21eb]
 
/usr/sbin/mysqld(Sql_cmd_call::execute(THD*)+0x90) [0x55a4390a2a80]
 
/usr/sbin/mysqld(mysql_execute_command(THD*)+0x134d) [0x55a4390a83dd]
 
/usr/sbin/mysqld(sp_instr_stmt::exec_core(THD*, unsigned int*)+0x36) [0x55a439020ca6]
 
/usr/sbin/mysqld(sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*)+0x99) [0x55a4390288e9]
 
/usr/sbin/mysqld(sp_instr_stmt::execute(THD*, unsigned int*)+0x205) [0x55a439028ee5]
 
/usr/sbin/mysqld(sp_head::execute(THD*, bool)+0x7ee) [0x55a43902494e]
 
/usr/sbin/mysqld(sp_head::execute_procedure(THD*, List<Item>*)+0x737) [0x55a439025a77]
 
/usr/sbin/mysqld(+0x55a48b) [0x55a4390a048b]
 
/usr/sbin/mysqld(+0x55c286) [0x55a4390a2286]
 
/usr/sbin/mysqld(Sql_cmd_call::execute(THD*)+0x90) [0x55a4390a2a80]
 
/usr/sbin/mysqld(mysql_execute_command(THD*)+0x134d) [0x55a4390a83dd]
 
/usr/sbin/mysqld(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool)+0x2fe) [0x55a4390b00fe]
 
/usr/sbin/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool)+0x2025) [0x55a4390b3085]
 
/usr/sbin/mysqld(do_command(THD*)+0x149) [0x55a4390b3c89]
 
/usr/sbin/mysqld(do_handle_one_connection(CONNECT*)+0x1aa) [0x55a4391785aa]
 
/usr/sbin/mysqld(handle_one_connection+0x3d) [0x55a4391786cd]
 
/lib64/libpthread.so.0(+0x7e25) [0x7f86373e3e25]
 
/lib64/libc.so.6(clone+0x6d) [0x7f8635a3634d]

Comment by Elena Stepanova [ 2017-12-24 ]

bar,

Here is what I've fished out from the whole thing so far. This is a debug assertion, and I'm not getting a crash on a release build; but assuming the assertion is not bogus, and something gets cleaned up that should not be, it might explain the variety of crashes and stack traces on non-debug builds, both here and maybe in MDEV-14657. While crashes are happening while calling completely different procedures, I believe all of them deep inside make a call to one and the same procedure which has the logic as below.

SET NAMES utf8;
 
CREATE TABLE t1(i INT);
 
CREATE PROCEDURE pr(tn VARCHAR(32))
 
  EXECUTE IMMEDIATE CONCAT('ANALYZE TABLE ',tn);
 
 
 
CALL pr('t1');

EXECUTE IMMEDIATE is not important, it can be traditional PREPARE/EXECUTE as well. Everything else seems important, namely utf8, procedure parameter, and concatenation within the statement.

10.2 a3476a5de2ee

 
mysqld: /data/src/10.2/sql/sql_prepare.cc:3940: bool Prepared_statement::prepare(const char*, uint): Assertion `thd->change_list.is_empty()' failed.
 
171224 18:31:21 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f38506b5ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x000055af38749161 in Prepared_statement::prepare (this=0x7f383800bae0, packet=0x7f383810f830 "ANALYZE TABLE t1", packet_len=16) at /data/src/10.2/sql/sql_prepare.cc:3940
 
#9  0x000055af3874b92b in Prepared_statement::execute_immediate (this=0x7f383800bae0, query=0x7f383810f830 "ANALYZE TABLE t1", query_len=16) at /data/src/10.2/sql/sql_prepare.cc:4837
 
#10 0x000055af3874669b in mysql_sql_stmt_execute_immediate (thd=0x7f3838000b00) at /data/src/10.2/sql/sql_prepare.cc:2874
 
#11 0x000055af38720500 in mysql_execute_command (thd=0x7f3838000b00) at /data/src/10.2/sql/sql_parse.cc:3468
 
#12 0x000055af38b11948 in sp_instr_stmt::exec_core (this=0x7f383800a200, thd=0x7f3838000b00, nextp=0x7f384a9901a4) at /data/src/10.2/sql/sp_head.cc:3264
 
#13 0x000055af38b10fb9 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7f383800a240, thd=0x7f3838000b00, nextp=0x7f384a9901a4, open_tables=false, instr=0x7f383800a200) at /data/src/10.2/sql/sp_head.cc:3027
 
#14 0x000055af38b115f3 in sp_instr_stmt::execute (this=0x7f383800a200, thd=0x7f3838000b00, nextp=0x7f384a9901a4) at /data/src/10.2/sql/sp_head.cc:3180
 
#15 0x000055af38b0c7db in sp_head::execute (this=0x7f38380091d8, thd=0x7f3838000b00, merge_da_on_success=true) at /data/src/10.2/sql/sp_head.cc:1336
 
#16 0x000055af38b0e87b in sp_head::execute_procedure (this=0x7f38380091d8, thd=0x7f3838000b00, args=0x7f38380053c8) at /data/src/10.2/sql/sp_head.cc:2135
 
#17 0x000055af3871eaf9 in do_execute_sp (thd=0x7f3838000b00, sp=0x7f38380091d8) at /data/src/10.2/sql/sql_parse.cc:2884
 
#18 0x000055af38727e6b in mysql_execute_command (thd=0x7f3838000b00) at /data/src/10.2/sql/sql_parse.cc:5805
 
#19 0x000055af3872dea2 in mysql_parse (thd=0x7f3838000b00, rawbuf=0x7f38380124e8 "CALL pr('t1')", length=13, parser_state=0x7f384a991200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7896
 
#20 0x000055af3871bdd4 in dispatch_command (command=COM_QUERY, thd=0x7f3838000b00, packet=0x7f3838170451 "CALL pr('t1')", packet_length=13, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1805
 
#21 0x000055af3871a732 in do_command (thd=0x7f3838000b00) at /data/src/10.2/sql/sql_parse.cc:1360
 
#22 0x000055af38868351 in do_handle_one_connection (connect=0x55af3c0c6110) at /data/src/10.2/sql/sql_connect.cc:1354
 
#23 0x000055af388680de in handle_one_connection (arg=0x55af3c0c6110) at /data/src/10.2/sql/sql_connect.cc:1260
 
#24 0x000055af38c86a76 in pfs_spawn_thread (arg=0x55af3c025000) at /data/src/10.2/storage/perfschema/pfs.cc:1863
 
#25 0x00007f385238c494 in start_thread (arg=0x7f384a992700) at pthread_create.c:333
 
#26 0x00007f385077293f in clone () from /lib/x86_64-linux-gnu/libc.so.6

This is reproducible on 10.2 and on 10.3 (both in the traditional mode and Oracle mode), so, I'm targeting it for 10.2 for now. If you decide that it can not account for the initially reported failure, then please extract it into another bug report (or tell me and I'll do it), and we'll return to the initial problem.

Comment by Alexander Barkov [ 2017-12-25 ]

This script also crashes the server:

DROP TABLE IF EXISTS t1;
 
DROP PROCEDURE IF EXISTS p1;
 
 
 
SET NAMES utf8;
 
CREATE TABLE t1(i INT);
 
CREATE PROCEDURE p1(tn VARCHAR(32)) EXECUTE IMMEDIATE CONCAT('SELECT ',tn);
 
CALL p1('t1');

Comment by Alexander Barkov [ 2017-12-25 ]

More scripts that crash the server:

DROP PROCEDURE IF EXISTS p1;
 
SET NAMES utf8;
 
CREATE PROCEDURE p1() EXECUTE IMMEDIATE CONCAT('SELECT ',CONVERT(RAND() USING latin1));
 
CALL p1();


DROP PROCEDURE IF EXISTS p1;
 
SET NAMES utf8;
 
DELIMITER $$
 
CREATE PROCEDURE p1()
 
BEGIN
 
  PREPARE stmt FROM CONCAT('SELECT ',CONVERT(RAND() USING latin1));
 
  EXECUTE stmt;
 
  DEALLOCATE PREPARE stmt;
 
END;
 
$$
 
DELIMITER ;
 
CALL p1();


DROP PROCEDURE IF EXISTS p1;
 
SET NAMES utf8;
 
CREATE PROCEDURE p1(a VARCHAR(10) CHARACTER SET utf8) EXECUTE IMMEDIATE 'SELECT ?' USING CONCAT(a, CONVERT(RAND() USING latin1));
 
CALL p1('x');


DROP PROCEDURE IF EXISTS p1;
 
SET NAMES utf8;
 
DELIMITER $$
 
CREATE PROCEDURE p1(a VARCHAR(10) CHARACTER SET utf8)
 
BEGIN
 
  PREPARE stmt FROM 'SELECT ?';
 
  EXECUTE stmt USING CONCAT(a, CONVERT(RAND() USING latin1));
 
  DEALLOCATE PREPARE stmt;
 
END;
 
$$
 
DELIMITER ;
 
CALL p1('x');

Comment by Alexander Barkov [ 2018-01-10 ]

Might be related to MDEV-14657.

Generated at Thu Feb 08 08:14:51 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.