[MDEV-7555] Server crashes in functions related to stored procedures Created: 2015-02-06  Updated: 2015-12-02  Resolved: 2015-05-19

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Procedure, Optimizer
Affects Version/s: 5.5.40
Fix Version/s: 5.5.45, 10.0.21

Type: Bug Priority: Major
Reporter: Geoff Montee (Inactive) Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: crash, verified

Issue Links:
Relates
relates to MDEV-7601 Server crashes in different ways whil... Closed

 Description   

Crashes were seen with the following stack traces:

stack_bottom = 0x7f82ebf32dd8 thread_stack 0x48000
 
mysys/stacktrace.c:247(my_print_stacktrace)[0xad47ae]
 
sql/signal_handler.cc:153(handle_fatal_signal)[0x6d388b]
 
/lib64/libpthread.so.0[0x3121c0f710]
 
sql/sql_string.h:240(String::free())[0x714227]
 
sql/item.h:1435(Item::delete_self())[0x5578e0]
 
sql/sql_class.h:761(~Query_arena)[0x7e2cd0]
 
sql/sp_head.cc:775(~sp_head)[0x7de9ad]
 
sql/sp_head.cc:528(sp_head::operator delete(void*, unsigned long))[0x7de9e1]
 
mysys/hash.c:115(my_hash_free_elements)[0xab898f]
 
sql/sp_cache.cc:132(sp_cache_clear(sp_cache**))[0x524553]
 
sql/sql_class.cc:1433(THD::cleanup())[0x55f197]
 
psi/mysql_thread.h:610(inline_mysql_mutex_lock)[0x504673]
 
sql/mysqld.cc:2607(one_thread_per_connection_end(THD*, bool))[0x5048f5]
 
sql/sql_connect.cc:1277(do_handle_one_connection(THD*))[0x64c080]
 
sql/sql_connect.cc:1183(handle_one_connection)[0x64c3ec]
 
/lib64/libpthread.so.0[0x3121c079d1]
 
/lib64/libc.so.6(clone+0x6d)[0x31214e886d]
 

stack_bottom = 0x7fc14df77dd8 thread_stack 0x48000
 
mysys/stacktrace.c:247(my_print_stacktrace)[0xad47ae]
 
sql/signal_handler.cc:153(handle_fatal_signal)[0x6d388b]
 
/lib64/libpthread.so.0[0x3b2000f710]
 
sql/sql_string.h:240(String::free())[0x714227]
 
sql/sql_parse.cc:667(cleanup_items(Item*))[0x581b11]
 
sql/sp_head.cc:1442(sp_head::execute(THD*, bool))[0x7de32d]
 
sql/sp_head.cc:2199(sp_head::execute_procedure(THD*, List<Item>*))[0x7df077]
 
sql/sql_parse.cc:4124(mysql_execute_command(THD*))[0x58bbac]
 
sql/sql_parse.cc:5799(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x58eb09]
 
sql/sql_parse.cc:1081(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x59009c]
 
sql/sql_connect.cc:1266(do_handle_one_connection(THD*))[0x64c34f]
 
sql/sql_connect.cc:1183(handle_one_connection)[0x64c3ec]
 
/lib64/libpthread.so.0[0x3b200079d1]
 
/lib64/libc.so.6(clone+0x6d)[0x3b1f8e88fd]
 

stack_bottom = 0x7f905e89ddd8 thread_stack 0x48000
 
mysys/stacktrace.c:247(my_print_stacktrace)[0xad47ae]
 
sql/signal_handler.cc:153(handle_fatal_signal)[0x6d388b]
 
/lib64/libpthread.so.0[0x3b2000f710]
 
sql/sql_string.h:240(String::free())[0x714227]
 
sql/sql_parse.cc:667(cleanup_items(Item*))[0x581b11]
 
sql/sp_head.cc:1442(sp_head::execute(THD*, bool))[0x7de32d]
 
sql/sp_head.cc:2199(sp_head::execute_procedure(THD*, List<Item>*))[0x7df077]
 
sql/sql_parse.cc:4124(mysql_execute_command(THD*))[0x58bbac]
 
sql/sql_parse.cc:5799(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x58eb09]
 
sql/sql_parse.cc:1081(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x59009c]
 
sql/sql_connect.cc:1266(do_handle_one_connection(THD*))[0x64c34f]
 
sql/sql_connect.cc:1183(handle_one_connection)[0x64c3ec]
 
/lib64/libpthread.so.0[0x3b200079d1]
 
/lib64/libc.so.6(clone+0x6d)[0x3b1f8e88fd]
 

stack_bottom = 0x7f10f349bdd8 thread_stack 0x48000
 
mysys/stacktrace.c:247(my_print_stacktrace)[0xad47ae]
 
sql/signal_handler.cc:153(handle_fatal_signal)[0x6d388b]
 
/lib64/libpthread.so.0[0x3b2000f710]
 
/lib64/libc.so.6(gsignal+0x35)[0x3b1f832625]
 
/lib64/libc.so.6(abort+0x175)[0x3b1f833e05]
 
/usr/lib64/libtcmalloc.so(_ZN8tcmalloc3LogENS_7LogModeEPKciNS_7LogItemES3_S3_S3_+0x22d)[0x7f151991aecd]
 
/usr/lib64/libtcmalloc.so(+0x16413)[0x7f151990e413]
 
/usr/lib64/libtcmalloc.so(tc_free+0x1fe)[0x7f151992f76e]
 
sql/sql_string.h:240(String::free())[0x714243]
 
sql/sql_parse.cc:667(cleanup_items(Item*))[0x581b11]
 
sql/sp_head.cc:1442(sp_head::execute(THD*, bool))[0x7de32d]
 
sql/sp_head.cc:2199(sp_head::execute_procedure(THD*, List<Item>*))[0x7df077]
 
sql/sql_parse.cc:4124(mysql_execute_command(THD*))[0x58bbac]
 
sql/sql_parse.cc:5799(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x58eb09]
 
sql/sql_parse.cc:1081(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x59009c]
 
sql/sql_connect.cc:1266(do_handle_one_connection(THD*))[0x64c34f]
 
sql/sql_connect.cc:1183(handle_one_connection)[0x64c3ec]
 
/lib64/libpthread.so.0[0x3b200079d1]
 
/lib64/libc.so.6(clone+0x6d)[0x3b1f8e88fd]
 

stack_bottom = 0x7f9593671dd8 thread_stack 0x48000
 
mysys/stacktrace.c:247(my_print_stacktrace)[0xad47ae]
 
sql/signal_handler.cc:153(handle_fatal_signal)[0x6d388b]
 
/lib64/libpthread.so.0[0x3b2000f710]
 
sql/sql_string.h:240(String::free())[0x714227]
 
sql/item.h:1435(Item::delete_self())[0x5578e0]
 
sql/sql_class.h:761(~Query_arena)[0x7e2cd0]
 
sql/sp_head.cc:775(~sp_head)[0x7de9ad]
 
sql/sp_head.cc:528(sp_head::operator delete(void*, unsigned long))[0x7de9e1]
 
mysys/hash.c:115(my_hash_free_elements)[0xab898f]
 
sql/sp_cache.cc:132(sp_cache_clear(sp_cache**))[0x524553]
 
sql/sql_class.cc:1433(THD::cleanup())[0x55f197]
 
psi/mysql_thread.h:610(inline_mysql_mutex_lock)[0x504673]
 
sql/mysqld.cc:2607(one_thread_per_connection_end(THD*, bool))[0x5048f5]
 
sql/sql_connect.cc:1277(do_handle_one_connection(THD*))[0x64c080]
 
sql/sql_connect.cc:1183(handle_one_connection)[0x64c3ec]
 
/lib64/libpthread.so.0[0x3b200079d1]
 
/lib64/libc.so.6(clone+0x6d)[0x3b1f8e88fd]



 Comments   
Comment by Elena Stepanova [ 2015-02-08 ]

One crash from which I saw the error log happened upon KILL_CONNECTION. Is it always the case?

Comment by Geoff Montee (Inactive) [ 2015-02-09 ]

It looks like it crashed upon KILL_CONNECTION two times, and it crashed while executing the stored procedure three times.

Comment by Michael Widenius [ 2015-02-20 ]

The crash seasm to happen while freeing memory used by the stored procedure.
This means that either the memory is freed twice or we have a memory overrun.

In both cases the bug is closely related to the stored procedure and to be able to find out the bug we would need:

  • A copy of the stored procedure
  • The definition of the tables that are used by the stored procedure.
    (.frm files are probably enough)

Another option would be to that we would provide a debug binary, mysqld would be started with the --core option and when/if it crashes again we would get access to the core file to debug this.

Comment by Elena Stepanova [ 2015-02-20 ]

See MDEV-7601 and its subtasks for intermediate results of stress tests which were run in attempt to reproduce the problem. It's not certain yet whether any of those is related, it will be analyzed.

Comment by Elena Stepanova [ 2015-02-22 ]

Got the following stack trace, the test case is in the comment to MDEV-7594

#3  <signal handler called>
 
#4  0x00007fa6cea35fa0 in ?? ()
 
#5  0x000000000060310b in Item::delete_self (this=0x7fa6cea345a8) at 5.5/sql/item.h:1434
 
#6  0x00000000005fd3cd in Query_arena::free_items (this=0x7fa6d694e078) at 5.5/sql/sql_class.cc:3160
 
#7  0x00000000005f8d6c in THD::cleanup_after_query (this=0x7fa6d694e060) at 5.5/sql/sql_class.cc:1883
 
#8  0x0000000000910920 in sp_head::execute (this=0x7fa6ce98e078, thd=0x7fa6d694e060, merge_da_on_success=true) at 5.5/sql/sp_head.cc:1449
 
#9  0x0000000000912610 in sp_head::execute_procedure (this=0x7fa6ce98e078, thd=0x7fa6d694e060, args=0x7fa6d6952000) at 5.5/sql/sp_head.cc:2199
 
#10 0x0000000000636c41 in mysql_execute_command (thd=0x7fa6d694e060) at 5.5/sql/sql_parse.cc:4123
 
#11 0x000000000063b20e in mysql_parse (thd=0x7fa6d694e060, rawbuf=0x7fa6ce951078 "CALL sp", length=7, parser_state=0x7fa6dec75620) at 5.5/sql/sql_parse.cc:5909
 
#12 0x000000000062ee51 in dispatch_command (command=COM_QUERY, thd=0x7fa6d694e060, packet=0x7fa6d6a74061 "", packet_length=7) at 5.5/sql/sql_parse.cc:1079
 
#13 0x000000000062dfdd in do_command (thd=0x7fa6d694e060) at 5.5/sql/sql_parse.cc:793
 
#14 0x000000000073072a in do_handle_one_connection (thd_arg=0x7fa6d694e060) at 5.5/sql/sql_connect.cc:1266
 
#15 0x00000000007301e9 in handle_one_connection (arg=0x7fa6d694e060) at 5.5/sql/sql_connect.cc:1181
 
#16 0x0000000000b66b61 in pfs_spawn_thread (arg=0x7fa6d69ca480) at 5.5/storage/perfschema/pfs.cc:1015
 
#17 0x00007fa6de8adb50 in start_thread (arg=<optimized out>) at pthread_create.c:304
 
#18 0x00007fa6dd1bb70d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
 
#19 0x0000000000000000 in ?? ()

Comment by Elena Stepanova [ 2015-02-22 ]

I suppose MDEV-7601 and its subtasks should be enough to consider this issue verified, at least for now. Assigning to Monty since he said he would look into the problem.

Comment by Michael Widenius [ 2015-05-19 ]

The problem was that select_lex->non_agg_fields was not properly reset for re-execution and this caused an overwrite of a random memory position.
The fix was move non_agg_fields from select_lext to JOIN, which is properly reset.

Fix pushed into the 5.5 tree.

Comment by Geoff Montee (Inactive) [ 2015-05-19 ]

Thanks for fixing this!

The JIRA issue currently says the fix should go into 5.5.40, but it will actually be going into 5.5.44, correct?

Generated at Thu Feb 08 07:20:29 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.