Execute the following repeatedly (using using multiple threads and random order, if you like, though these are likely not necessary from current observations).
Note that there is a significant SHUTDOWN command in the testcase, so standard run methods (like MTR/CLI) may not work. We have a specialized script for this in the mariadb-qa (multirun_mysqld_text) which can be setup to produce this issue in 1-2 minutes. Please let me know if this would help and I will set it up for you.
The issue tends to reproduce quite easily with 200 non-random client threads against approx 10 mysqld's.
[Current thread is 1 (Thread 0x14955d4ea700 (LWP 173779))]
(gdb) bt
#0 __pthread_kill (threadid=<optimized out>, signo=signo@entry=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1 0x00005652e630a3f3 in my_write_core (sig=sig@entry=11) at /test/10.6_dbg/mysys/stacktrace.c:424
#2 0x00005652e5aaf195 in handle_fatal_signal (sig=11) at /test/10.6_dbg/sql/signal_handler.cc:331
#3 <signal handler called>
#4 0x00005652e5cd553a in Event_queue::recalculate_activation_times (this=0x1494ec02a470, thd=thd@entry=0x1494e002ebd8) at /test/10.6_dbg/sql/event_queue.cc:464
#5 0x00005652e5cd3aa5 in Event_scheduler::run (this=this@entry=0x1494ec02a5d0, thd=0x1494e002ebd8) at /test/10.6_dbg/sql/event_scheduler.cc:485
#6 0x00005652e5cd3da8 in event_scheduler_thread (arg=arg@entry=0x1494e003d138) at /test/10.6_dbg/sql/event_scheduler.cc:236
#7 0x00005652e5df0ce9 in pfs_spawn_thread (arg=0x1494e003d1e8) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
#8 0x0000149575aed609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#9 0x00001495756dc293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
[Current thread is 1 (Thread 0x145e17a9b640 (LWP 89133))]
(gdb) bt
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22394356479552) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=22394356479552) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=22394356479552, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 0x0000145e4ffec476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 0x0000145e4ffd27f3 in __GI_abort () at ./stdlib/abort.c:79
#5 0x0000556ed332d9a9 in safe_mutex_lock (mp=0x556ed60e9300, my_flags=<optimized out>, file=0x556ed35d6008 "/test/11.0_dbg/sql/event_scheduler.cc", line=733) at /test/11.0_dbg/mysys/thr_mutex.c:297
#6 0x0000556ed2e47198 in inline_mysql_mutex_lock (src_line=733, src_file=0x556ed35d6008 "/test/11.0_dbg/sql/event_scheduler.cc", that=0x556ed60e9300) at /test/11.0_dbg/include/mysql/psi/mysql_thread.h:750
#7 Event_scheduler::lock_data (this=this@entry=0x556ed60e9300, func=func@entry=0x556ed35d5f20 "is_running", line=line@entry=609) at /test/11.0_dbg/sql/event_scheduler.cc:733
#8 0x0000556ed2e47210 in Event_scheduler::is_running (this=this@entry=0x556ed60e9300) at /test/11.0_dbg/sql/event_scheduler.cc:609
#9 0x0000556ed2e474f9 in Event_scheduler::run (this=this@entry=0x556ed60e9300, thd=0x145e00027638) at /test/11.0_dbg/sql/event_scheduler.cc:487
#10 0x0000556ed2e47631 in event_scheduler_thread (arg=0x145e0001a198) at /test/11.0_dbg/sql/event_scheduler.cc:236
#11 0x0000145e5003eb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#12 0x0000145e500d0a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
[Current thread is 1 (Thread 0x14dd424e5640 (LWP 3549264))]
(gdb) bt
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22940532758080) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=22940532758080) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=22940532758080, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 0x000014dd5eff9476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 0x000014dd5efdf7f3 in __GI_abort () at ./stdlib/abort.c:79
#5 0x00005619431169a9 in safe_mutex_lock (mp=0x561944a77460, my_flags=<optimized out>, file=0x5619433bf008 "/test/11.0_dbg/sql/event_scheduler.cc", line=733) at /test/11.0_dbg/mysys/thr_mutex.c:297
#6 0x0000561942c30198 in inline_mysql_mutex_lock (src_line=733, src_file=0x5619433bf008 "/test/11.0_dbg/sql/event_scheduler.cc", that=0x561944a77460) at /test/11.0_dbg/include/mysql/psi/mysql_thread.h:750
#7 Event_scheduler::lock_data (this=this@entry=0x561944a77460, func=func@entry=0x5619433bef20 "is_running", line=line@entry=609) at /test/11.0_dbg/sql/event_scheduler.cc:733
#8 0x0000561942c30210 in Event_scheduler::is_running (this=this@entry=0x561944a77460) at /test/11.0_dbg/sql/event_scheduler.cc:609
#9 0x0000561942c304f9 in Event_scheduler::run (this=this@entry=0x561944a77460, thd=0x14dd00023608) at /test/11.0_dbg/sql/event_scheduler.cc:487
#10 0x0000561942c30631 in event_scheduler_thread (arg=0x14dd0001a198) at /test/11.0_dbg/sql/event_scheduler.cc:236
#11 0x000014dd5f04bb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#12 0x000014dd5f0dda00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
[Current thread is 1 (Thread 0x14b59262f640 (LWP 2940588))]
(gdb) bt
#0 hashcmp (hash=hash@entry=0x556089c6b968, pos=pos@entry=0x8f8f8f8f0, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8) at /test/11.0_dbg/mysys/hash.c:379
#1 0x0000556087f71fec in my_hash_first_from_hash_value (hash=hash@entry=0x556089c6b968, hash_value=<optimized out>, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8, current_record=current_record@entry=0x14b59262db7c) at /test/11.0_dbg/mysys/hash.c:290
#2 0x0000556087f7208d in my_hash_first (hash=0x556089c6b968, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8, current_record=current_record@entry=0x14b59262db7c) at /test/11.0_dbg/mysys/hash.c:262
#3 0x0000556087f720ed in my_hash_search (hash=<optimized out>, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8) at /test/11.0_dbg/mysys/hash.c:235
#4 0x0000556087f9091c in safe_mutex_lock (mp=0x556088a0dae0 <LOCK_thread_id>, my_flags=<optimized out>, file=0x556088051004 "/test/11.0_dbg/sql/mysqld.cc", line=9866) at /test/11.0_dbg/mysys/thr_mutex.c:335
#5 0x000055608750c349 in inline_mysql_mutex_lock (src_line=9866, src_file=0x556088051004 "/test/11.0_dbg/sql/mysqld.cc", that=0x556088a0dae0 <LOCK_thread_id>) at /test/11.0_dbg/include/mysql/psi/mysql_thread.h:750
#6 next_thread_id () at /test/11.0_dbg/sql/mysqld.cc:9866
#7 0x0000556087aaa2a0 in Event_scheduler::start (this=0x556089a48300, err_no=err_no@entry=0x14b59262dcbc) at /test/11.0_dbg/sql/event_scheduler.cc:404
#8 0x000055608775c8cf in Events::start (err_no=err_no@entry=0x14b59262dcbc) at /test/11.0_dbg/sql/events.cc:1136
#9 0x0000556087793b0d in event_scheduler_update (self=<optimized out>, thd=0x14b55c000d58, type=<optimized out>) at /test/11.0_dbg/sql/sys_vars.cc:1159
#10 0x000055608754e817 in sys_var::update (this=0x556088a39e40 <Sys_event_scheduler>, thd=0x14b55c000d58, var=0x14b55c013260) at /test/11.0_dbg/sql/set_var.cc:208
#11 0x000055608754ed07 in set_var::update (this=<optimized out>, thd=<optimized out>) at /test/11.0_dbg/sql/set_var.cc:863
#12 0x000055608754ff30 in sql_set_variables (thd=thd@entry=0x14b55c000d58, var_list=var_list@entry=0x14b55c005ee8, free=free@entry=true) at /test/11.0_dbg/sql/set_var.cc:745
#13 0x000055608762a543 in mysql_execute_command (thd=thd@entry=0x14b55c000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/11.0_dbg/sql/sql_parse.cc:5038
#14 0x000055608762e934 in mysql_parse (thd=thd@entry=0x14b55c000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14b59262e2c0) at /test/11.0_dbg/sql/sql_parse.cc:8000
#15 0x0000556087630ac8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14b55c000d58, packet=packet@entry=0x14b55c00ae09 "SET GLOBAL event_scheduler=TRUE", packet_length=packet_length@entry=31, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_class.h:243
#16 0x0000556087632921 in do_command (thd=0x14b55c000d58, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_parse.cc:1407
#17 0x000055608777c9ea in do_handle_one_connection (connect=<optimized out>, connect@entry=0x556089c6ba88, put_in_cache=put_in_cache@entry=true) at /test/11.0_dbg/sql/sql_connect.cc:1416
#18 0x000055608777cc4e in handle_one_connection (arg=0x556089c6ba88) at /test/11.0_dbg/sql/sql_connect.cc:1318
#19 0x000014b5aef46b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#20 0x000014b5aefd8a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
Roel Van de Paar
added a comment - - edited With this sporadic but simple testcase:
SET GLOBAL event_scheduler= TRUE ;
SHUTDOWN;
SET GLOBAL event_scheduler= TRUE ;
SET GLOBAL event_scheduler= TRUE ;
SET GLOBAL event_scheduler= TRUE ;
This error can be observed after a number of runs against the CLI (not sure how to translate this testcase to MTR):
11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Debug)
Got error 22 when trying to lock mutex LOCK_scheduler_state at /test/11.0_dbg/sql/event_scheduler.cc, line 733
And stack smashing is present:
11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Debug)
Core was generated by `/test/MD090123-mariadb-11.0.1-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0 0x0000151ff12b4a7c in ?? ()
[Current thread is 1 (LWP 3757915)]
(gdb) bt
#0 0x0000151ff12b4a7c in ?? ()
#1 0x000055aa7e119408 in ?? ()
#2 0x0000151ff129fa09 in ?? ()
#3 0x00000000fbad8001 in ?? ()
#4 0x0000151fd857db30 in ?? ()
#5 0x0000151fd857db30 in ?? ()
#6 0x0000151fd857db30 in ?? ()
#7 0x0000151fd857db30 in ?? ()
#8 0x0000151fd857db34 in ?? ()
#9 0x0000151fd857db93 in ?? ()
#10 0x0000151fd857db30 in ?? ()
#11 0x0000151fd857db93 in ?? ()
#12 0x0000000000000000 in ?? ()
With the same testcase (again looping it - about 5-10 times), we can see this stack at times:
11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Debug)
Core was generated by `/test/MD090123-mariadb-11.0.1-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22394356479552)
at ./nptl/pthread_kill.c:44
[Current thread is 1 (Thread 0x145e17a9b640 (LWP 89133))]
(gdb) bt
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22394356479552) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=22394356479552) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=22394356479552, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 0x0000145e4ffec476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 0x0000145e4ffd27f3 in __GI_abort () at ./stdlib/abort.c:79
#5 0x0000556ed332d9a9 in safe_mutex_lock (mp=0x556ed60e9300, my_flags=<optimized out>, file=0x556ed35d6008 "/test/11.0_dbg/sql/event_scheduler.cc", line=733) at /test/11.0_dbg/mysys/thr_mutex.c:297
#6 0x0000556ed2e47198 in inline_mysql_mutex_lock (src_line=733, src_file=0x556ed35d6008 "/test/11.0_dbg/sql/event_scheduler.cc", that=0x556ed60e9300) at /test/11.0_dbg/include/mysql/psi/mysql_thread.h:750
#7 Event_scheduler::lock_data (this=this@entry=0x556ed60e9300, func=func@entry=0x556ed35d5f20 "is_running", line=line@entry=609) at /test/11.0_dbg/sql/event_scheduler.cc:733
#8 0x0000556ed2e47210 in Event_scheduler::is_running (this=this@entry=0x556ed60e9300) at /test/11.0_dbg/sql/event_scheduler.cc:609
#9 0x0000556ed2e474f9 in Event_scheduler::run (this=this@entry=0x556ed60e9300, thd=0x145e00027638) at /test/11.0_dbg/sql/event_scheduler.cc:487
#10 0x0000556ed2e47631 in event_scheduler_thread (arg=0x145e0001a198) at /test/11.0_dbg/sql/event_scheduler.cc:236
#11 0x0000145e5003eb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#12 0x0000145e500d0a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
Or this stack, but less frequently:
11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Debug)
Core was generated by `/test/MD090123-mariadb-11.0.1-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22940532758080)
at ./nptl/pthread_kill.c:44
[Current thread is 1 (Thread 0x14dd424e5640 (LWP 3549264))]
(gdb) bt
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22940532758080) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=22940532758080) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=22940532758080, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 0x000014dd5eff9476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 0x000014dd5efdf7f3 in __GI_abort () at ./stdlib/abort.c:79
#5 0x00005619431169a9 in safe_mutex_lock (mp=0x561944a77460, my_flags=<optimized out>, file=0x5619433bf008 "/test/11.0_dbg/sql/event_scheduler.cc", line=733) at /test/11.0_dbg/mysys/thr_mutex.c:297
#6 0x0000561942c30198 in inline_mysql_mutex_lock (src_line=733, src_file=0x5619433bf008 "/test/11.0_dbg/sql/event_scheduler.cc", that=0x561944a77460) at /test/11.0_dbg/include/mysql/psi/mysql_thread.h:750
#7 Event_scheduler::lock_data (this=this@entry=0x561944a77460, func=func@entry=0x5619433bef20 "is_running", line=line@entry=609) at /test/11.0_dbg/sql/event_scheduler.cc:733
#8 0x0000561942c30210 in Event_scheduler::is_running (this=this@entry=0x561944a77460) at /test/11.0_dbg/sql/event_scheduler.cc:609
#9 0x0000561942c304f9 in Event_scheduler::run (this=this@entry=0x561944a77460, thd=0x14dd00023608) at /test/11.0_dbg/sql/event_scheduler.cc:487
#10 0x0000561942c30631 in event_scheduler_thread (arg=0x14dd0001a198) at /test/11.0_dbg/sql/event_scheduler.cc:236
#11 0x000014dd5f04bb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#12 0x000014dd5f0dda00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
Or this stack, but also less frequently:
11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Debug)
Core was generated by `/test/MD090123-mariadb-11.0.1-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 hashcmp (hash=hash@entry=0x556089c6b968, pos=pos@entry=0x8f8f8f8f0,
key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001",
length=length@entry=8) at /test/11.0_dbg/mysys/hash.c:379
379 rec_key= (uchar*) my_hash_key(hash, pos->data, &rec_keylength, 1);
[Current thread is 1 (Thread 0x14b59262f640 (LWP 2940588))]
(gdb) bt
#0 hashcmp (hash=hash@entry=0x556089c6b968, pos=pos@entry=0x8f8f8f8f0, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8) at /test/11.0_dbg/mysys/hash.c:379
#1 0x0000556087f71fec in my_hash_first_from_hash_value (hash=hash@entry=0x556089c6b968, hash_value=<optimized out>, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8, current_record=current_record@entry=0x14b59262db7c) at /test/11.0_dbg/mysys/hash.c:290
#2 0x0000556087f7208d in my_hash_first (hash=0x556089c6b968, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8, current_record=current_record@entry=0x14b59262db7c) at /test/11.0_dbg/mysys/hash.c:262
#3 0x0000556087f720ed in my_hash_search (hash=<optimized out>, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8) at /test/11.0_dbg/mysys/hash.c:235
#4 0x0000556087f9091c in safe_mutex_lock (mp=0x556088a0dae0 <LOCK_thread_id>, my_flags=<optimized out>, file=0x556088051004 "/test/11.0_dbg/sql/mysqld.cc", line=9866) at /test/11.0_dbg/mysys/thr_mutex.c:335
#5 0x000055608750c349 in inline_mysql_mutex_lock (src_line=9866, src_file=0x556088051004 "/test/11.0_dbg/sql/mysqld.cc", that=0x556088a0dae0 <LOCK_thread_id>) at /test/11.0_dbg/include/mysql/psi/mysql_thread.h:750
#6 next_thread_id () at /test/11.0_dbg/sql/mysqld.cc:9866
#7 0x0000556087aaa2a0 in Event_scheduler::start (this=0x556089a48300, err_no=err_no@entry=0x14b59262dcbc) at /test/11.0_dbg/sql/event_scheduler.cc:404
#8 0x000055608775c8cf in Events::start (err_no=err_no@entry=0x14b59262dcbc) at /test/11.0_dbg/sql/events.cc:1136
#9 0x0000556087793b0d in event_scheduler_update (self=<optimized out>, thd=0x14b55c000d58, type=<optimized out>) at /test/11.0_dbg/sql/sys_vars.cc:1159
#10 0x000055608754e817 in sys_var::update (this=0x556088a39e40 <Sys_event_scheduler>, thd=0x14b55c000d58, var=0x14b55c013260) at /test/11.0_dbg/sql/set_var.cc:208
#11 0x000055608754ed07 in set_var::update (this=<optimized out>, thd=<optimized out>) at /test/11.0_dbg/sql/set_var.cc:863
#12 0x000055608754ff30 in sql_set_variables (thd=thd@entry=0x14b55c000d58, var_list=var_list@entry=0x14b55c005ee8, free=free@entry=true) at /test/11.0_dbg/sql/set_var.cc:745
#13 0x000055608762a543 in mysql_execute_command (thd=thd@entry=0x14b55c000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/11.0_dbg/sql/sql_parse.cc:5038
#14 0x000055608762e934 in mysql_parse (thd=thd@entry=0x14b55c000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14b59262e2c0) at /test/11.0_dbg/sql/sql_parse.cc:8000
#15 0x0000556087630ac8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14b55c000d58, packet=packet@entry=0x14b55c00ae09 "SET GLOBAL event_scheduler=TRUE", packet_length=packet_length@entry=31, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_class.h:243
#16 0x0000556087632921 in do_command (thd=0x14b55c000d58, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_parse.cc:1407
#17 0x000055608777c9ea in do_handle_one_connection (connect=<optimized out>, connect@entry=0x556089c6ba88, put_in_cache=put_in_cache@entry=true) at /test/11.0_dbg/sql/sql_connect.cc:1416
#18 0x000055608777cc4e in handle_one_connection (arg=0x556089c6ba88) at /test/11.0_dbg/sql/sql_connect.cc:1318
#19 0x000014b5aef46b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#20 0x000014b5aefd8a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
mysql_mutex_lock(&LOCK_scheduler_state); ### <<<<-------- Line 733
mutex_last_locked_in_func= func;
mutex_last_locked_at_line= line;
mutex_scheduler_data_locked= TRUE;
DBUG_VOID_RETURN;
}
Roel Van de Paar
added a comment - In connection with the last comment, here is the code around /test/11.0_dbg/sql/event_scheduler.cc, line 733:
/*
Auxiliary function for locking LOCK_scheduler_state. Used
by the LOCK_DATA macro.
SYNOPSIS
Event_scheduler::lock_data()
func Which function is requesting mutex lock
line On which line mutex lock is requested
*/
void
Event_scheduler::lock_data( const char *func, uint line)
{
DBUG_ENTER( "Event_scheduler::lock_data" );
DBUG_PRINT( "enter" , ( "func=%s line=%u" , func, line));
mysql_mutex_lock(&LOCK_scheduler_state); ### <<<<-------- Line 733
mutex_last_locked_in_func= func;
mutex_last_locked_at_line= line;
mutex_scheduler_data_locked= TRUE;
DBUG_VOID_RETURN;
}
The issue seems to be straightforward - an attempt [race?] to lock a mutex after shutdown was already initiated. Perhaps the solution is adding a check, or preventing the race?
Another thought (based on seeing other bugs in this area, but not directly related here) would be for the scheduler to always check whether a shutdown is in progress and not start executing a query if so.
Roel Van de Paar
added a comment - - edited The issue seems to be straightforward - an attempt [race?] to lock a mutex after shutdown was already initiated. Perhaps the solution is adding a check, or preventing the race?
Another thought (based on seeing other bugs in this area, but not directly related here) would be for the scheduler to always check whether a shutdown is in progress and not start executing a query if so.
I have also seen an optimized 11.0.1 build (rev b075191ba8598af6aff5549e6e19f6255aef258a) crash without a core file (not normal) and without any message in the error log (on more than one occasion).
Roel Van de Paar
added a comment - - edited I have also seen an optimized 11.0.1 build (rev b075191ba8598af6aff5549e6e19f6255aef258a) crash without a core file (not normal) and without any message in the error log (on more than one occasion).
Roel Van de Paar
added a comment - Given the stack smashing I ran the testcase through a ASAN+UBSAN build, and there is a heap-use-after-free:
10.11.2 70be59913c90e93fe5136d6f6df03c4254aa515d (Optimized, UBASAN)
==2890587==ERROR: AddressSanitizer: heap-use-after-free on address 0x60f000001248 at pc 0x559209b23cf7 bp 0x14d0e84e4260 sp 0x14d0e84e4250
WRITE of size 8 at 0x60f000001248 thread T15
#0 0x559209b23cf6 in Event_scheduler::start(int*) /test/10.11_opt_san/sql/event_scheduler.cc:433
#1 0x5592080c4ad8 in event_scheduler_update /test/10.11_opt_san/sql/sys_vars.cc:1159
#2 0x5592070a5afa in sys_var::update(THD*, set_var*) /test/10.11_opt_san/sql/set_var.cc:208
#3 0x5592070a9336 in set_var::update(THD*) /test/10.11_opt_san/sql/set_var.cc:863
#4 0x5592070b1b6d in sql_set_variables(THD*, List<set_var_base>*, bool) /test/10.11_opt_san/sql/set_var.cc:745
#5 0x559207727f06 in mysql_execute_command(THD*, bool) /test/10.11_opt_san/sql/sql_parse.cc:5038
#6 0x559207740d82 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/10.11_opt_san/sql/sql_parse.cc:8000
#7 0x55920774e7e5 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /test/10.11_opt_san/sql/sql_parse.cc:1894
#8 0x559207757f40 in do_command(THD*, bool) /test/10.11_opt_san/sql/sql_parse.cc:1407
#9 0x55920803471c in do_handle_one_connection(CONNECT*, bool) /test/10.11_opt_san/sql/sql_connect.cc:1416
#10 0x559208036d1c in handle_one_connection /test/10.11_opt_san/sql/sql_connect.cc:1318
#11 0x14d10a809b42 in start_thread nptl/pthread_create.c:442
#12 0x14d10a89b9ff (/lib/x86_64-linux-gnu/libc.so.6+0x1269ff)
0x60f000001248 is located 56 bytes inside of 168-byte region [0x60f000001210,0x60f0000012b8)
freed by thread T0 here:
#0 0x559206e6ed07 in operator delete(void*) (/test/UBASAN_MD070123-mariadb-10.11.2-linux-x86_64-opt/bin/mariadbd+0x7a22d07)
#1 0x559207f7ce99 in Events::deinit() /test/10.11_opt_san/sql/events.cc:1000
#2 0x559206edc2de in close_connections /test/10.11_opt_san/sql/mysqld.cc:1788
#3 0x559206edc2de in mysqld_main(int, char**) /test/10.11_opt_san/sql/mysqld.cc:6022
#4 0x14d10a79ed8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58
previously allocated by thread T0 here:
#0 0x559206e6e1e7 in operator new(unsigned long) (/test/UBASAN_MD070123-mariadb-10.11.2-linux-x86_64-opt/bin/mariadbd+0x7a221e7)
#1 0x559207f828a2 in Events::init(THD*, bool) /test/10.11_opt_san/sql/events.cc:958
#2 0x559206edae2e in mysqld_main(int, char**) /test/10.11_opt_san/sql/mysqld.cc:5887
#3 0x14d10a79ed8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58
Thread T15 created by T0 here:
#0 0x559206e106c5 in pthread_create (/test/UBASAN_MD070123-mariadb-10.11.2-linux-x86_64-opt/bin/mariadbd+0x79c46c5)
#1 0x559206ec4cfe in create_thread_to_handle_connection(CONNECT*) /test/10.11_opt_san/sql/mysqld.cc:6102
#2 0x559206ed712f in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /test/10.11_opt_san/sql/mysqld.cc:6223
#3 0x559206ed80b7 in handle_connections_sockets() /test/10.11_opt_san/sql/mysqld.cc:6347
#4 0x559206edb11d in mysqld_main(int, char**) /test/10.11_opt_san/sql/mysqld.cc:5997
#5 0x14d10a79ed8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58
SUMMARY: AddressSanitizer: heap-use-after-free /test/10.11_opt_san/sql/event_scheduler.cc:433 in Event_scheduler::start(int*)
Shadow bytes around the buggy address:
0x0c1e7fff81f0: 00 00 00 00 00 00 00 00 00 00 00 00 00 fa fa fa
0x0c1e7fff8200: fa fa fa fa fa fa fd fd fd fd fd fd fd fd fd fd
0x0c1e7fff8210: fd fd fd fd fd fd fd fd fd fd fd fa fa fa fa fa
0x0c1e7fff8220: fa fa fa fa 00 00 00 00 00 00 00 00 00 00 00 00
0x0c1e7fff8230: 00 00 00 00 00 00 00 00 00 fa fa fa fa fa fa fa
=>0x0c1e7fff8240: fa fa fd fd fd fd fd fd fd[fd]fd fd fd fd fd fd
0x0c1e7fff8250: fd fd fd fd fd fd fd fa fa fa fa fa fa fa fa fa
0x0c1e7fff8260: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
0x0c1e7fff8270: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
0x0c1e7fff8280: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
0x0c1e7fff8290: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
Shadow byte legend (one shadow byte represents 8 application bytes):
Addressable: 00
Partially addressable: 01 02 03 04 05 06 07
Heap left redzone: fa
Freed heap region: fd
Stack left redzone: f1
Stack mid redzone: f2
Stack right redzone: f3
Stack after return: f5
Stack use after scope: f8
Global redzone: f9
Global init order: f6
Poisoned by user: f7
Container overflow: fc
Array cookie: ac
Intra object redzone: bb
ASan internal: fe
Left alloca redzone: ca
Right alloca redzone: cb
Shadow gap: cc
==2890587==ABORTING
230118 19:59:08 [ERROR] mysqld got signal 6 ;
People
Oleksandr Byelkin
Roel Van de Paar
Votes:
0Vote for this issue
Watchers:
4Start watching this issue
Dates
Created:
Updated:
Git Integration
Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.
With this sporadic but simple testcase:
SHUTDOWN;
This error can be observed after a number of runs against the CLI (not sure how to translate this testcase to MTR):
11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Debug)
Got error 22 when trying to lock mutex LOCK_scheduler_state at /test/11.0_dbg/sql/event_scheduler.cc, line 733
And stack smashing is present:
11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Debug)
Core was generated by `/test/MD090123-mariadb-11.0.1-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0 0x0000151ff12b4a7c in ?? ()
[Current thread is 1 (LWP 3757915)]
(gdb) bt
#0 0x0000151ff12b4a7c in ?? ()
#1 0x000055aa7e119408 in ?? ()
#2 0x0000151ff129fa09 in ?? ()
#3 0x00000000fbad8001 in ?? ()
#4 0x0000151fd857db30 in ?? ()
#5 0x0000151fd857db30 in ?? ()
#6 0x0000151fd857db30 in ?? ()
#7 0x0000151fd857db30 in ?? ()
#8 0x0000151fd857db34 in ?? ()
#9 0x0000151fd857db93 in ?? ()
#10 0x0000151fd857db30 in ?? ()
#11 0x0000151fd857db93 in ?? ()
#12 0x0000000000000000 in ?? ()
With the same testcase (again looping it - about 5-10 times), we can see this stack at times:
11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Debug)
Core was generated by `/test/MD090123-mariadb-11.0.1-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22394356479552)
at ./nptl/pthread_kill.c:44
[Current thread is 1 (Thread 0x145e17a9b640 (LWP 89133))]
(gdb) bt
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22394356479552) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=22394356479552) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=22394356479552, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 0x0000145e4ffec476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 0x0000145e4ffd27f3 in __GI_abort () at ./stdlib/abort.c:79
#5 0x0000556ed332d9a9 in safe_mutex_lock (mp=0x556ed60e9300, my_flags=<optimized out>, file=0x556ed35d6008 "/test/11.0_dbg/sql/event_scheduler.cc", line=733) at /test/11.0_dbg/mysys/thr_mutex.c:297
#6 0x0000556ed2e47198 in inline_mysql_mutex_lock (src_line=733, src_file=0x556ed35d6008 "/test/11.0_dbg/sql/event_scheduler.cc", that=0x556ed60e9300) at /test/11.0_dbg/include/mysql/psi/mysql_thread.h:750
#7 Event_scheduler::lock_data (this=this@entry=0x556ed60e9300, func=func@entry=0x556ed35d5f20 "is_running", line=line@entry=609) at /test/11.0_dbg/sql/event_scheduler.cc:733
#8 0x0000556ed2e47210 in Event_scheduler::is_running (this=this@entry=0x556ed60e9300) at /test/11.0_dbg/sql/event_scheduler.cc:609
#9 0x0000556ed2e474f9 in Event_scheduler::run (this=this@entry=0x556ed60e9300, thd=0x145e00027638) at /test/11.0_dbg/sql/event_scheduler.cc:487
#10 0x0000556ed2e47631 in event_scheduler_thread (arg=0x145e0001a198) at /test/11.0_dbg/sql/event_scheduler.cc:236
#11 0x0000145e5003eb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#12 0x0000145e500d0a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
Or this stack, but less frequently:
11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Debug)
Core was generated by `/test/MD090123-mariadb-11.0.1-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22940532758080)
at ./nptl/pthread_kill.c:44
[Current thread is 1 (Thread 0x14dd424e5640 (LWP 3549264))]
(gdb) bt
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22940532758080) at ./nptl/pthread_kill.c:44
#1 __pthread_kill_internal (signo=6, threadid=22940532758080) at ./nptl/pthread_kill.c:78
#2 __GI___pthread_kill (threadid=22940532758080, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3 0x000014dd5eff9476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4 0x000014dd5efdf7f3 in __GI_abort () at ./stdlib/abort.c:79
#5 0x00005619431169a9 in safe_mutex_lock (mp=0x561944a77460, my_flags=<optimized out>, file=0x5619433bf008 "/test/11.0_dbg/sql/event_scheduler.cc", line=733) at /test/11.0_dbg/mysys/thr_mutex.c:297
#6 0x0000561942c30198 in inline_mysql_mutex_lock (src_line=733, src_file=0x5619433bf008 "/test/11.0_dbg/sql/event_scheduler.cc", that=0x561944a77460) at /test/11.0_dbg/include/mysql/psi/mysql_thread.h:750
#7 Event_scheduler::lock_data (this=this@entry=0x561944a77460, func=func@entry=0x5619433bef20 "is_running", line=line@entry=609) at /test/11.0_dbg/sql/event_scheduler.cc:733
#8 0x0000561942c30210 in Event_scheduler::is_running (this=this@entry=0x561944a77460) at /test/11.0_dbg/sql/event_scheduler.cc:609
#9 0x0000561942c304f9 in Event_scheduler::run (this=this@entry=0x561944a77460, thd=0x14dd00023608) at /test/11.0_dbg/sql/event_scheduler.cc:487
#10 0x0000561942c30631 in event_scheduler_thread (arg=0x14dd0001a198) at /test/11.0_dbg/sql/event_scheduler.cc:236
#11 0x000014dd5f04bb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#12 0x000014dd5f0dda00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
Or this stack, but also less frequently:
11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Debug)
Core was generated by `/test/MD090123-mariadb-11.0.1-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 hashcmp (hash=hash@entry=0x556089c6b968, pos=pos@entry=0x8f8f8f8f0,
key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001",
length=length@entry=8) at /test/11.0_dbg/mysys/hash.c:379
379 rec_key= (uchar*) my_hash_key(hash, pos->data, &rec_keylength, 1);
[Current thread is 1 (Thread 0x14b59262f640 (LWP 2940588))]
(gdb) bt
#0 hashcmp (hash=hash@entry=0x556089c6b968, pos=pos@entry=0x8f8f8f8f0, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8) at /test/11.0_dbg/mysys/hash.c:379
#1 0x0000556087f71fec in my_hash_first_from_hash_value (hash=hash@entry=0x556089c6b968, hash_value=<optimized out>, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8, current_record=current_record@entry=0x14b59262db7c) at /test/11.0_dbg/mysys/hash.c:290
#2 0x0000556087f7208d in my_hash_first (hash=0x556089c6b968, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8, current_record=current_record@entry=0x14b59262db7c) at /test/11.0_dbg/mysys/hash.c:262
#3 0x0000556087f720ed in my_hash_search (hash=<optimized out>, key=key@entry=0x556088a0db58 <LOCK_thread_id+120> "\005\001", length=length@entry=8) at /test/11.0_dbg/mysys/hash.c:235
#4 0x0000556087f9091c in safe_mutex_lock (mp=0x556088a0dae0 <LOCK_thread_id>, my_flags=<optimized out>, file=0x556088051004 "/test/11.0_dbg/sql/mysqld.cc", line=9866) at /test/11.0_dbg/mysys/thr_mutex.c:335
#5 0x000055608750c349 in inline_mysql_mutex_lock (src_line=9866, src_file=0x556088051004 "/test/11.0_dbg/sql/mysqld.cc", that=0x556088a0dae0 <LOCK_thread_id>) at /test/11.0_dbg/include/mysql/psi/mysql_thread.h:750
#6 next_thread_id () at /test/11.0_dbg/sql/mysqld.cc:9866
#7 0x0000556087aaa2a0 in Event_scheduler::start (this=0x556089a48300, err_no=err_no@entry=0x14b59262dcbc) at /test/11.0_dbg/sql/event_scheduler.cc:404
#8 0x000055608775c8cf in Events::start (err_no=err_no@entry=0x14b59262dcbc) at /test/11.0_dbg/sql/events.cc:1136
#9 0x0000556087793b0d in event_scheduler_update (self=<optimized out>, thd=0x14b55c000d58, type=<optimized out>) at /test/11.0_dbg/sql/sys_vars.cc:1159
#10 0x000055608754e817 in sys_var::update (this=0x556088a39e40 <Sys_event_scheduler>, thd=0x14b55c000d58, var=0x14b55c013260) at /test/11.0_dbg/sql/set_var.cc:208
#11 0x000055608754ed07 in set_var::update (this=<optimized out>, thd=<optimized out>) at /test/11.0_dbg/sql/set_var.cc:863
#12 0x000055608754ff30 in sql_set_variables (thd=thd@entry=0x14b55c000d58, var_list=var_list@entry=0x14b55c005ee8, free=free@entry=true) at /test/11.0_dbg/sql/set_var.cc:745
#13 0x000055608762a543 in mysql_execute_command (thd=thd@entry=0x14b55c000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/11.0_dbg/sql/sql_parse.cc:5038
#14 0x000055608762e934 in mysql_parse (thd=thd@entry=0x14b55c000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14b59262e2c0) at /test/11.0_dbg/sql/sql_parse.cc:8000
#15 0x0000556087630ac8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14b55c000d58, packet=packet@entry=0x14b55c00ae09 "SET GLOBAL event_scheduler=TRUE", packet_length=packet_length@entry=31, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_class.h:243
#16 0x0000556087632921 in do_command (thd=0x14b55c000d58, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_parse.cc:1407
#17 0x000055608777c9ea in do_handle_one_connection (connect=<optimized out>, connect@entry=0x556089c6ba88, put_in_cache=put_in_cache@entry=true) at /test/11.0_dbg/sql/sql_connect.cc:1416
#18 0x000055608777cc4e in handle_one_connection (arg=0x556089c6ba88) at /test/11.0_dbg/sql/sql_connect.cc:1318
#19 0x000014b5aef46b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#20 0x000014b5aefd8a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81