[MDEV-25890] Trying to lock mutex ... when the mutex was already locked | SIGABRT in safe_mutex_lock | Hangs and cross-mysqld interaction Created: 2021-06-10  Updated: 2021-12-21  Resolved: 2021-12-21

Status: Closed
Project: MariaDB Server
Component/s: Binary Protocol, Galera, Storage Engine - InnoDB
Affects Version/s: 10.6
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Roel Van de Paar Assignee: Jan Lindström (Inactive)
Resolution: Duplicate Votes: 0
Labels: cross-mysqld-interaction, hang, regression

Issue Links:
Duplicate
is duplicated by MDEV-27039 Trying to lock mutex ... when the mut... Closed
Relates
relates to MDEV-21452 Use condition variables and normal mu... Closed

 Description   

Possibly related to MDEV-25874 and MDEV-21452.

Issue is 10.6 only, debug crashes in safe_mutex_lock.

# mysqld options required for replay: --log_bin
CREATE TABLE a (c INT) ENGINE=InnoDB;
SET GLOBAL expire_logs_days=11;
SET GLOBAL innodb_disallow_writes=ON;
SET GLOBAL binlog_checksum=CRC32;

Leads to:

2021-06-10 21:49:40 0 [Note] /test/MD050621-mariadb-10.6.2-linux-x86_64-dbg/bin/mysqld: ready for connections.
Version: '10.6.2-MariaDB-debug-log'  socket: '/test/MD050621-mariadb-10.6.2-linux-x86_64-dbg/socket.sock'  port: 10148  MariaDB Server
safe_mutex: Trying to lock mutex at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc, line 18992, when the mutex was already locked at /test/10.6_dbg/sql/sys_vars_shared.h, line 56 in thread T@17

Early analysis by Marko, ref this code:

void innodb_wait_allow_writes()
{
  if (UNIV_UNLIKELY(innodb_disallow_writes))
  {
    mysql_mutex_lock(&LOCK_global_system_variables);

10.6.2 06dd151bb86ad5b87d4d46011f36da1289c01074 (Debug)

Core was generated by `/test/MD050621-mariadb-10.6.2-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
[Current thread is 1 (Thread 0x14b335967700 (LWP 1802597))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000014b34c822859 in __GI_abort () at abort.c:79
#2  0x000055cb061f13e8 in safe_mutex_lock (mp=0x55cb06ca6520 <LOCK_global_system_variables>, my_flags=my_flags@entry=0, file=file@entry=0x55cb065a4a48 "/test/10.6_dbg/storage/innobase/handler/ha_innodb.cc", line=line@entry=18992) at /test/10.6_dbg/mysys/thr_mutex.c:262
#3  0x000055cb05d82f46 in inline_mysql_mutex_lock (src_line=18992, src_file=0x55cb065a4a48 "/test/10.6_dbg/storage/innobase/handler/ha_innodb.cc", that=<optimized out>) at /test/10.6_dbg/include/mysql/psi/mysql_thread.h:750
#4  innodb_wait_allow_writes () at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:18992
#5  0x000055cb05e61ad9 in os_file_write_func (type=@0x55cb065c8fe0: {bpage = 0x0, node = 0x0, type = IORequest::WRITE_SYNC}, name=<optimized out>, name@entry=0x55cb079668d0 "./ib_logfile0", file=file@entry=10, buf=buf@entry=0x14b3359fe000, offset=<optimized out>, offset@entry=37376, n=<optimized out>, n@entry=1024) at /test/10.6_dbg/storage/innobase/os/os0file.cc:2958
#6  0x000055cb05e2fe71 in pfs_os_file_write_func (src_line=318, src_file=0x55cb065c7dd8 "/test/10.6_dbg/storage/innobase/log/log0log.cc", n=1024, offset=37376, buf=0x14b3359fe000, file={m_file = 10, m_psi = <optimized out>}, name=0x55cb079668d0 "./ib_logfile0", type=@0x55cb065c8fe0: {bpage = 0x0, node = 0x0, type = IORequest::WRITE_SYNC}) at /test/10.6_dbg/storage/innobase/include/os0file.h:94
#7  file_os_io::write (this=<optimized out>, path=0x55cb079668d0 "./ib_logfile0", offset=37376, buf=<optimized out>) at /test/10.6_dbg/storage/innobase/log/log0log.cc:318
#8  0x000055cb05e309db in log_file_t::write (this=this@entry=0x55cb075331e0 <log_sys+480>, offset=offset@entry=37376, buf={data_ = 0x14b3359fe000 "\200", size_ = 1024}) at /usr/include/c++/9/bits/basic_string.h:2300
#9  0x000055cb05e31862 in log_t::file::write (this=this@entry=0x55cb075331c0 <log_sys+448>, offset=offset@entry=37376, buf={data_ = 0x14b3359fe000 "\200", size_ = 1024}) at /test/10.6_dbg/include/span.h:121
#10 0x000055cb05e32de4 in log_write_buf (new_data_offset=<optimized out>, start_lsn=44032, pad_len=0, len=1024, buf=0x14b3359fe000 "\200") at /test/10.6_dbg/include/span.h:66
#11 log_write (rotate_key=<optimized out>) at /test/10.6_dbg/storage/innobase/log/log0log.cc:753
#12 log_write_up_to (lsn=<optimized out>, flush_to_disk=flush_to_disk@entry=true, rotate_key=rotate_key@entry=false, callback=callback@entry=0x0) at /test/10.6_dbg/storage/innobase/log/log0log.cc:816
#13 0x000055cb05e33037 in log_buffer_flush_to_disk (sync=<optimized out>) at /usr/include/c++/9/bits/atomic_base.h:413
#14 0x000055cb05d72708 in innobase_flush_logs (hton=0x55cb07851978, binlog_group_flush=binlog_group_flush@entry=true) at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:1593
#15 0x000055cb05d727e2 in innobase_flush_logs (hton=<optimized out>) at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:1626
#16 0x000055cb0599297e in flush_handlerton (thd=thd@entry=0x0, plugin=<optimized out>, arg=arg@entry=0x0) at /test/10.6_dbg/sql/handler.cc:2741
#17 0x000055cb056cd0ff in plugin_foreach_with_mask (thd=thd@entry=0x0, func=func@entry=0x55cb0599295c <flush_handlerton(THD*, plugin_ref, void*)>, type=type@entry=1, state_mask=state_mask@entry=8, arg=arg@entry=0x0) at /test/10.6_dbg/sql/sql_plugin.cc:2510
#18 0x000055cb05999380 in ha_flush_logs () at /test/10.6_dbg/sql/handler.cc:2747
#19 0x000055cb05aeb1d2 in MYSQL_BIN_LOG::purge (this=this@entry=0x55cb06cda800 <mysql_bin_log>) at /test/10.6_dbg/sql/log.cc:7046
#20 0x000055cb05aef6ff in MYSQL_BIN_LOG::checkpoint_and_purge (this=this@entry=0x55cb06cda800 <mysql_bin_log>, binlog_id=binlog_id@entry=1) at /test/10.6_dbg/sql/log.cc:7058
#21 0x000055cb05af92da in binlog_checksum_update (thd=<optimized out>, var=<optimized out>, var_ptr=<optimized out>, save=<optimized out>) at /test/10.6_dbg/sql/log.cc:10875
#22 0x000055cb056ce25b in sys_var_pluginvar::global_update (this=0x55cb07789510, thd=0x14b2fc000db8, var=0x14b2fc0142b0) at /test/10.6_dbg/sql/sql_plugin.cc:3624
#23 0x000055cb055c24cc in sys_var::update (this=0x55cb07789510, thd=0x14b2fc000db8, var=0x14b2fc0142b0) at /test/10.6_dbg/sql/set_var.cc:207
#24 0x000055cb055c29f9 in set_var::update (this=<optimized out>, thd=<optimized out>) at /test/10.6_dbg/sql/set_var.cc:858
#25 0x000055cb055c3d3f in sql_set_variables (thd=thd@entry=0x14b2fc000db8, var_list=var_list@entry=0x14b2fc006038, free=free@entry=true) at /test/10.6_dbg/sql/set_var.cc:745
#26 0x000055cb056c36ad in mysql_execute_command (thd=thd@entry=0x14b2fc000db8) at /test/10.6_dbg/sql/sql_parse.cc:5027
#27 0x000055cb056acadc in mysql_parse (thd=thd@entry=0x14b2fc000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14b335966400) at /test/10.6_dbg/sql/sql_parse.cc:8016
#28 0x000055cb056bb646 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14b2fc000db8, packet=packet@entry=0x14b2fc00b889 "SET GLOBAL binlog_checksum=CRC32", packet_length=packet_length@entry=32, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_class.h:1340
#29 0x000055cb056bea26 in do_command (thd=0x14b2fc000db8, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_parse.cc:1406
#30 0x000055cb05822ec2 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55cb07d56558, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
#31 0x000055cb058234c7 in handle_one_connection (arg=arg@entry=0x55cb07d56558) at /test/10.6_dbg/sql/sql_connect.cc:1312
#32 0x000055cb05ccf03a in pfs_spawn_thread (arg=0x55cb07c23d78) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
#33 0x000014b34cd30609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#34 0x000014b34c91f293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95



 Comments   
Comment by Roel Van de Paar [ 2021-11-13 ]

Raising prio as there is some serious locking issue in the server somewhere (seems to be focused around sql/sys_vars_shared.h, line 56) causing locking crashing in debug, hangs and cross-mysqld interaction (i.e. one mysqld affecting another with nothing shared). See MDEV-27039

Comment by Nayuta Yanagisawa (Inactive) [ 2021-12-21 ]

jplindst FYI. The bug also seems to be introduced by 49ff2cb. See my comment on MDEV-27039.

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