[MDEV-22154] safe_mutex: Trying to lock mutex at <somewhere> , when the mutex was already locked at sql_parse.cc Created: 2020-04-05  Updated: 2022-11-15  Resolved: 2022-11-15

Status: Closed
Project: MariaDB Server
Component/s: Admin statements, wsrep
Affects Version/s: 10.4, 10.5
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Jan Lindström (Inactive)
Resolution: Duplicate Votes: 0
Labels: None
Environment:

Galera 26.4.4(r4599)

Issue Links:
Relates
relates to MDEV-22458 Server with WSREP hangs after INSERT,... Closed
relates to MDEV-22460 safe_mutex: Found wrong usage of mute... Closed

 Description   

Test case 1: <somewhere> == sql_parse.cc, line ~9017

 
--source include/galera_cluster.inc
 
 
 
--connect(con1,localhost,root,,)
 
--let $conid= `SELECT CONNECTION_ID()`
 
 
 
--connection default
 
 
 
--error ER_TARGET_NOT_EXPLAINABLE
 
eval SHOW EXPLAIN FOR $conid;
 
--error ER_TARGET_NOT_EXPLAINABLE
 
eval SHOW EXPLAIN FOR $conid;
 
 
 
# Cleanup
 
--disconnect con1

10.4 aa7f2578

 
safe_mutex: Trying to lock mutex at /data/src/10.4/sql/sql_parse.cc, line 9017, when the mutex was already locked at /data/src/10.4/sql/sql_parse.cc, line 9017 in thread T@20
 
200406  1:02:30 [ERROR] mysqld got signal 6 ;
 
 
 
#5  0x00007f8d1cba5535 in __GI_abort () at abort.c:79
 
#6  0x000055dbb0ba542f in safe_mutex_lock (mp=0x62b000120e10, my_flags=0, file=0x55dbb0e896c0 "/data/src/10.4/sql/sql_parse.cc", line=9017) at /data/src/10.4/mysys/thr_mutex.c:265
 
#7  0x000055dbaf05510a in inline_mysql_mutex_lock (that=0x62b000120e10, src_file=0x55dbb0e896c0 "/data/src/10.4/sql/sql_parse.cc", src_line=9017) at /data/src/10.4/include/mysql/psi/mysql_thread.h:702
 
#8  0x000055dbaf094578 in find_thread_callback (thd=0x62b00011f270, arg=0x7f8d02dde680) at /data/src/10.4/sql/sql_parse.cc:9017
 
#9  0x000055dbaf09f9b5 in THD_list::iterate<find_thread_callback_arg> (this=0x55dbb2612be0 <server_threads>, action=0x55dbaf09435b <find_thread_callback(THD*, find_thread_callback_arg*)>, arg=0x7f8d02dde680) at /data/src/10.4/sql/sql_class.h:7023
 
#10 0x000055dbaf09469f in find_thread_by_id (id=18, query_id=false) at /data/src/10.4/sql/sql_parse.cc:9029
 
#11 0x000055dbaf21ee92 in fill_show_explain (thd=0x62b0000cb270, table=0x62b0000d30f0, cond=0x0) at /data/src/10.4/sql/sql_show.cc:3157
 
#12 0x000055dbaf260c23 in get_schema_tables_result (join=0x62b0000d4680, executed_place=PROCESSED_BY_JOIN_EXEC) at /data/src/10.4/sql/sql_show.cc:8913
 
#13 0x000055dbaf13b98e in JOIN::exec_inner (this=0x62b0000d4680) at /data/src/10.4/sql/sql_select.cc:4416
 
#14 0x000055dbaf13989a in JOIN::exec (this=0x62b0000d4680) at /data/src/10.4/sql/sql_select.cc:4241
 
#15 0x000055dbaf13d780 in mysql_select (thd=0x62b0000cb270, tables=0x62b0000d30f0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684619520, result=0x62b0000d4650, unit=0x62b0000cf198, select_lex=0x62b0000cf990) at /data/src/10.4/sql/sql_select.cc:4673
 
#16 0x000055dbaf10f9b8 in handle_select (thd=0x62b0000cb270, lex=0x62b0000cf0d8, result=0x62b0000d4650, setup_tables_done_option=0) at /data/src/10.4/sql/sql_select.cc:410
 
#17 0x000055dbaf083f3b in execute_sqlcom_select (thd=0x62b0000cb270, all_tables=0x62b0000d30f0) at /data/src/10.4/sql/sql_parse.cc:6359
 
#18 0x000055dbaf06fcc7 in mysql_execute_command (thd=0x62b0000cb270) at /data/src/10.4/sql/sql_parse.cc:3898
 
#19 0x000055dbaf08d47a in mysql_parse (thd=0x62b0000cb270, rawbuf=0x62b0000d2290 "SHOW EXPLAIN FOR 18", length=19, parser_state=0x7f8d02de45d0, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7900
 
#20 0x000055dbaf08beca in wsrep_mysql_parse (thd=0x62b0000cb270, rawbuf=0x62b0000d2290 "SHOW EXPLAIN FOR 18", length=19, parser_state=0x7f8d02de45d0, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7704
 
#21 0x000055dbaf0620c0 in dispatch_command (command=COM_QUERY, thd=0x62b0000cb270, packet=0x6290002df271 "SHOW EXPLAIN FOR 18", packet_length=19, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1827
 
#22 0x000055dbaf05ea98 in do_command (thd=0x62b0000cb270) at /data/src/10.4/sql/sql_parse.cc:1359
 
#23 0x000055dbaf436dd4 in do_handle_one_connection (connect=0x61100006de30) at /data/src/10.4/sql/sql_connect.cc:1412
 
#24 0x000055dbaf436676 in handle_one_connection (arg=0x61100006de30) at /data/src/10.4/sql/sql_connect.cc:1316
 
#25 0x000055dbb0a7466d in pfs_spawn_thread (arg=0x61600007daf0) at /data/src/10.4/storage/perfschema/pfs.cc:1869
 
#26 0x00007f8d1d42dfa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
 
#27 0x00007f8d1cc7c4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Test case 2: <somewhere> == repl_failsafe.cc, line ~177

 
--source include/galera_cluster.inc
 
 
 
--connect(con1,localhost,root,,)
 
--let $conid= `SELECT CONNECTION_ID()`
 
 
 
--connection default
 
 
 
--error ER_TARGET_NOT_EXPLAINABLE
 
eval SHOW EXPLAIN FOR $conid;
 
SHOW SLAVE HOSTS;
 
 
 
# Cleanup
 
--disconnect con1


safe_mutex: Trying to lock mutex at /data/src/10.4/sql/repl_failsafe.cc, line 177, when the mutex was already locked at /data/src/10.4/sql/sql_parse.cc, line 9017 in thread T@20
 
200406  1:04:09 [ERROR] mysqld got signal 6 ;
 
 
 
#6  0x00005589cfe7e42f in safe_mutex_lock (mp=0x62b000120e10, my_flags=0, file=0x5589d00d7560 "/data/src/10.4/sql/repl_failsafe.cc", line=177) at /data/src/10.4/mysys/thr_mutex.c:265
 
#7  0x00005589ce0a058e in inline_mysql_mutex_lock (that=0x62b000120e10, src_file=0x5589d00d7560 "/data/src/10.4/sql/repl_failsafe.cc", src_line=177) at /data/src/10.4/include/mysql/psi/mysql_thread.h:702
 
#8  0x00005589ce0a0f77 in show_slave_hosts_callback (thd=0x62b00011f270, protocol=0x62b0000cb838) at /data/src/10.4/sql/repl_failsafe.cc:177
 
#9  0x00005589ce0a9d5b in THD_list::iterate<Protocol> (this=0x5589d18ebbe0 <server_threads>, action=0x5589ce0a0f45 <show_slave_hosts_callback(THD*, Protocol*)>, arg=0x62b0000cb838) at /data/src/10.4/sql/sql_class.h:7023
 
#10 0x00005589ce0a17c6 in show_slave_hosts (thd=0x62b0000cb270) at /data/src/10.4/sql/repl_failsafe.cc:238
 
#11 0x00005589ce3492bb in mysql_execute_command (thd=0x62b0000cb270) at /data/src/10.4/sql/sql_parse.cc:4000
 
#12 0x00005589ce36647a in mysql_parse (thd=0x62b0000cb270, rawbuf=0x62b0000d2290 "SHOW SLAVE HOSTS", length=16, parser_state=0x7fe096f615d0, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7900
 
#13 0x00005589ce364eca in wsrep_mysql_parse (thd=0x62b0000cb270, rawbuf=0x62b0000d2290 "SHOW SLAVE HOSTS", length=16, parser_state=0x7fe096f615d0, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7704
 
#14 0x00005589ce33b0c0 in dispatch_command (command=COM_QUERY, thd=0x62b0000cb270, packet=0x6290002df271 "", packet_length=16, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1827
 
#15 0x00005589ce337a98 in do_command (thd=0x62b0000cb270) at /data/src/10.4/sql/sql_parse.cc:1359
 
#16 0x00005589ce70fdd4 in do_handle_one_connection (connect=0x61100006de30) at /data/src/10.4/sql/sql_connect.cc:1412
 
#17 0x00005589ce70f676 in handle_one_connection (arg=0x61100006de30) at /data/src/10.4/sql/sql_connect.cc:1316
 
#18 0x00005589cfd4d66d in pfs_spawn_thread (arg=0x61600007daf0) at /data/src/10.4/storage/perfschema/pfs.cc:1869
 
#19 0x00007fe0b15befa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
 
#20 0x00007fe0b0e0d4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Test case 3: <somewhere> == sql_show.cc, line ~157

 
--source include/galera_cluster.inc
 
 
 
--connect(con1,localhost,root,,)
 
--let $conid= `SELECT CONNECTION_ID()`
 
 
 
--connection default
 
 
 
--error ER_TARGET_NOT_EXPLAINABLE
 
eval SHOW EXPLAIN FOR $conid;
 
SHOW PROCESSLIST;
 
 
 
# Cleanup
 
--disconnect con1


safe_mutex: Trying to lock mutex at /data/src/10.4/sql/sql_show.cc, line 157, when the mutex was already locked at /data/src/10.4/sql/sql_parse.cc, line 9017 in thread T@20
 
200406  1:06:09 [ERROR] mysqld got signal 6 ;
 
 
 
#5  0x00007faae3273535 in __GI_abort () at abort.c:79
 
#6  0x000055d43fa4e42f in safe_mutex_lock (mp=0x62b000120e10, my_flags=1, file=0x55d43fd71340 "/data/src/10.4/sql/sql_show.cc", line=157) at /data/src/10.4/mysys/thr_mutex.c:265
 
#7  0x000055d43e0af2ea in inline_mysql_mutex_trylock (that=0x62b000120e10, src_file=0x55d43fd71340 "/data/src/10.4/sql/sql_show.cc", src_line=157) at /data/src/10.4/include/mysql/psi/mysql_thread.h:745
 
#8  0x000055d43e0b0c00 in trylock_short (mutex=0x62b000120e10) at /data/src/10.4/sql/sql_show.cc:157
 
#9  0x000055d43e0c4a68 in list_callback (tmp=0x62b00011f270, arg=0x7faac949e340) at /data/src/10.4/sql/sql_show.cc:2847
 
#10 0x000055d43e112291 in THD_list::iterate<list_callback_arg> (this=0x55d4414bbbe0 <server_threads>, action=0x55d43e0c4154 <list_callback(THD*, list_callback_arg*)>, arg=0x7faac949e340) at /data/src/10.4/sql/sql_class.h:7023
 
#11 0x000055d43e0c5cb2 in mysqld_list_processes (thd=0x62b0000cb270, user=0x0, verbose=false) at /data/src/10.4/sql/sql_show.cc:2961
 
#12 0x000055d43df2066a in mysql_execute_command (thd=0x62b0000cb270) at /data/src/10.4/sql/sql_parse.cc:4882
 
#13 0x000055d43df3647a in mysql_parse (thd=0x62b0000cb270, rawbuf=0x62b0000d2290 "SHOW PROCESSLIST", length=16, parser_state=0x7faac94a35d0, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7900
 
#14 0x000055d43df34eca in wsrep_mysql_parse (thd=0x62b0000cb270, rawbuf=0x62b0000d2290 "SHOW PROCESSLIST", length=16, parser_state=0x7faac94a35d0, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7704
 
#15 0x000055d43df0b0c0 in dispatch_command (command=COM_QUERY, thd=0x62b0000cb270, packet=0x6290002df271 "", packet_length=16, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1827
 
#16 0x000055d43df07a98 in do_command (thd=0x62b0000cb270) at /data/src/10.4/sql/sql_parse.cc:1359
 
#17 0x000055d43e2dfdd4 in do_handle_one_connection (connect=0x61100006de30) at /data/src/10.4/sql/sql_connect.cc:1412
 
#18 0x000055d43e2df676 in handle_one_connection (arg=0x61100006de30) at /data/src/10.4/sql/sql_connect.cc:1316
 
#19 0x000055d43f91d66d in pfs_spawn_thread (arg=0x61600007daf0) at /data/src/10.4/storage/perfschema/pfs.cc:1869
 
#20 0x00007faae3afbfa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
 
#21 0x00007faae334a4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Test case 4: <somewhere> == wsrep_mutex.h, line ~34

 
--source include/galera_cluster.inc
 
 
 
--connection default
 
--let $conid= `SELECT CONNECTION_ID()`
 
 
 
--error ER_TARGET_NOT_EXPLAINABLE
 
eval SHOW EXPLAIN FOR $conid;


safe_mutex: Trying to lock mutex at /data/src/10.4/sql/wsrep_mutex.h, line 34, when the mutex was already locked at /data/src/10.4/sql/sql_parse.cc, line 9017 in thread T@20
 
200406  1:13:37 [ERROR] mysqld got signal 6 ;
 
 
 
#5  0x00007f57a1257535 in __GI_abort () at abort.c:79
 
#6  0x0000557c436ee42f in safe_mutex_lock (mp=0x62b0000cce10, my_flags=0, file=0x557c43993260 "/data/src/10.4/sql/wsrep_mutex.h", line=34) at /data/src/10.4/mysys/thr_mutex.c:265
 
#7  0x0000557c41a8b316 in inline_mysql_mutex_lock (that=0x62b0000cce10, src_file=0x557c43993260 "/data/src/10.4/sql/wsrep_mutex.h", src_line=34) at /data/src/10.4/include/mysql/psi/mysql_thread.h:702
 
#8  0x0000557c41ac541f in Wsrep_mutex::lock (this=0x62b0000d13d0) at /data/src/10.4/sql/wsrep_mutex.h:34
 
#9  0x0000557c418ecf62 in wsrep::unique_lock<wsrep::mutex>::unique_lock (this=0x7f578747c990, mutex=...) at /data/src/10.4/wsrep-lib/include/wsrep/lock.hpp:37
 
#10 0x0000557c438e8e57 in wsrep::transaction::before_rollback (this=0x62b0000d1470) at /data/src/10.4/wsrep-lib/src/transaction.cpp:623
 
#11 0x0000557c41a5b3f3 in wsrep::client_state::before_rollback (this=0x62b0000d1408) at /data/src/10.4/wsrep-lib/include/wsrep/client_state.hpp:496
 
#12 0x0000557c41ba13ca in wsrep_before_rollback (thd=0x62b0000cb270, all=true) at /data/src/10.4/sql/wsrep_trans_observer.h:364
 
#13 0x0000557c41ba23aa in wsrep_commit_empty (thd=0x62b0000cb270, all=true) at /data/src/10.4/sql/wsrep_trans_observer.h:513
 
#14 0x0000557c41bcb84b in mysql_execute_command (thd=0x62b0000cb270) at /data/src/10.4/sql/sql_parse.cc:6256
 
#15 0x0000557c41bd647a in mysql_parse (thd=0x62b0000cb270, rawbuf=0x62b0000d2290 "SHOW EXPLAIN FOR 15", length=19, parser_state=0x7f57874825d0, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7900
 
#16 0x0000557c41bd4eca in wsrep_mysql_parse (thd=0x62b0000cb270, rawbuf=0x62b0000d2290 "SHOW EXPLAIN FOR 15", length=19, parser_state=0x7f57874825d0, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7704
 
#17 0x0000557c41bab0c0 in dispatch_command (command=COM_QUERY, thd=0x62b0000cb270, packet=0x6290002d5271 "SHOW EXPLAIN FOR 15", packet_length=19, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1827
 
#18 0x0000557c41ba7a98 in do_command (thd=0x62b0000cb270) at /data/src/10.4/sql/sql_parse.cc:1359
 
#19 0x0000557c41f7fdd4 in do_handle_one_connection (connect=0x61100006de30) at /data/src/10.4/sql/sql_connect.cc:1412
 
#20 0x0000557c41f7f676 in handle_one_connection (arg=0x61100006de30) at /data/src/10.4/sql/sql_connect.cc:1316
 
#21 0x0000557c435bd66d in pfs_spawn_thread (arg=0x61600007daf0) at /data/src/10.4/storage/perfschema/pfs.cc:1869
 
#22 0x00007f57a1adffa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
 
#23 0x00007f57a132e4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

I suppose there are other conflicts.

Reproducible on 10.4, 10.5.
Not reproducible on 10.3.
Not reproducible without wsrep_on=ON.

 Comments   
Comment by Ramesh Sivaraman [ 2022-02-04 ]

jplindst Could not reproduce safe mutex locking issues on latest 10.4 build.

10.4.23 12cad0c3468d734e041d4ef0cd5a26d2a28606fc (Debug)

 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
 
[..]
 
galera.safemutex1 'innodb'               [ pass ]   2017
 
[..]
 
galera.safemutex2 'innodb'               [ pass ]   2015
 
[..]
 
galera.safemutex3 'innodb'               [ pass ]   2015
 
connection node_2;
 
connection node_1;
 
connection default;
 
SHOW EXPLAIN FOR 36;
 
ERROR HY000: Target is not running an EXPLAINable command
 
galera.safemutex4 'innodb'               [ pass ]   2017
 
--------------------------------------------------------------------------
 
The servers were restarted 0 times
 
Spent 8.064 of 28 seconds executing testcases
 
 
 
Completed: All 4 tests were successful.

Comment by Elena Stepanova [ 2022-11-15 ]

Probably fixed in the scope of MDEV-22458.

Generated at Thu Feb 08 09:12:36 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.