[MDEV-33357] ALTER TABLE ... IMPORT TABLESPACE causes innodb_fatal_semaphore_wait_threshold was exceeded for dict_sys.latch. Created: 2024-02-01  Updated: 2024-02-02

Status: Open
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Performance Schema, Server, Storage Engine - InnoDB
Affects Version/s: 10.6.16
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Tilman Vogel Assignee: Sergei Golubchik
Resolution: Unresolved Votes: 1
Labels: hang, lock-free
Environment:

Ubuntu 22.04.3 LTS
Linux 5.15.0-72-generic #79-Ubuntu SMP Wed Apr 19 08:22:18 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Attachments: File maria-error.log    
Issue Links:
Relates
relates to MDEV-33360 fil_node_t::handle had better not be ... Confirmed

 Description   

Attempting a partial restore from `mariabackup` using https://github.com/tvogel/run-mariabackup leads the mariadbd to abort during running
```
ALTER TABLE .... IMPORT TABLESPACE;
```

I will attach the log entry from `error.log` and will upload an all-thread stack-trace with symbols to private FTP under this issue number because of sensitive data in the back-trace.

 Comments   
Comment by Tilman Vogel [ 2024-02-01 ]

Backtrace uploaded ftp://ftp.mariadb.org/private/MDEV-33357-backtrace.log.xz

Comment by Marko Mäkelä [ 2024-02-02 ]

Thank you for providing the stack traces. There are 484 threads. I see an ALTER TABLE…IMPORT TABLESPACE here (obfuscating the file name):

mariadb-10.6.16

 
Thread 9 (Thread 0x7f9a6c0b7640 (LWP 2517495)):
 
#0  0x0000563594d31210 in my_hash_sort_bin (cs=<optimized out>, key=0x7f9a6c0b53c8 "e.ibd", len=45, nr1=0x7f9a6c0b5130, nr2=0x7f9a6c0b5138) at ./strings/ctype-bin.c:302
 
#1  0x0000563594d1f63e in my_ci_hash_sort (nr2=0x7f9a6c0b5138, nr1=0x7f9a6c0b5130, len=<optimized out>, key=<optimized out>, ci=<optimized out>) at ./include/m_ctype.h:1211
 
#2  calc_hash (cs=<optimized out>, key=<optimized out>, keylen=<optimized out>) at ./mysys/lf_hash.cc:328
 
#3  0x0000563594d2030f in lf_hash_search (hash=0x563595e3eae0 <pfs_filename_hash>, pins=0x56359786d850, key=0x7f9a6c0b53a0, keylen=45) at ./mysys/lf_hash.cc:542
 
#4  0x0000563594aa66f9 in find_or_create_file (thread=<optimized out>, klass=0x5635977a79c0, filename=filename@entry=0x563597f41a48 "./XXXXXXX/YYYYYYYYYYYYYYYYYe.ibd", len=<optimized out>, create=create@entry=tr
 
ue) at ./storage/perfschema/pfs_instr.cc:854
 
#5  0x0000563594a8bb96 in pfs_end_file_open_wait_v1 (locker=0x7f9a6c0b5840, result=<optimized out>) at ./storage/perfschema/pfs.cc:4458
 
#6  0x0000563594c756af in pfs_os_file_create_func (purpose=61, src_file=0x563594f91ec8 "./storage/innobase/fil/fil0fil.cc", src_line=374, src_file=0x563594f91ec8 "./storage/innobase/fil/fil0fil.cc", success=0x7f
 
9a6c0b5837, read_only=<optimized out>, type=100, purpose=61, create_mode=179, name=0x563597f41a48 "./XXXXXXX/YYYYYYYYYYYYYYYYYe.ibd", key=<optimized out>) at ./storage/innobase/include/os0file.inl:170
 
#7  fil_node_open_file_low (node=0x563597f419d8) at ./storage/innobase/fil/fil0fil.cc:374
 
#8  0x00005635944f33ed in fil_space_t::prepare_acquired (this=this@entry=0x563597f41888) at ./storage/innobase/fil/fil0fil.cc:673
 
#9  0x00005635944f4ccc in fil_space_t::acquire_if_not_stopped (this=0x563597f41888) at ./storage/innobase/fil/fil0crypt.cc:1345
 
#10 fil_space_t::acquire_if_not_stopped (this=<optimized out>) at ./storage/innobase/fil/fil0crypt.cc:1337
 
#11 fil_crypt_default_encrypt_tables_fill () at ./storage/innobase/fil/fil0crypt.cc:2141
 
#12 0x0000563594c7cab0 in fil_crypt_set_encrypt_tables (val=0) at ./storage/innobase/fil/fil0crypt.cc:2217
 
#13 0x0000563594b32e56 in ha_innobase::discard_or_import_tablespace (this=0x7f9a08243db0, discard=<optimized out>) at ./storage/innobase/handler/ha_innodb.cc:13447

Based on this stack trace, it looks like you have enabled some performance_schema instrumentation. This thread is not blocked in any wait, but it might take excessive amount of time.

This thread is not holding dict_sys.latch, but it is holding fil_system.mutex. That one is blocking many threads that are invoking fil_space_t::get() in buf_read_page(). The following is the dict_sys.latch holder, waiting for the fil_system.mutex. I have obscured the table name:

mariadb-10.6.16

 
Thread 7 (Thread 0x7f9a5d95b640 (LWP 2518383)):
 
#0  futex_wait (private=0, expected=2, futex_word=0x563595e8f6a8 <fil_system+40>) at ../sysdeps/nptl/futex-internal.h:146
 
#1  __GI___lll_lock_wait (futex=futex@entry=0x563595e8f6a8 <fil_system+40>, private=0) at ./nptl/lowlevellock.c:49
 
#2  0x00007f9a76e6e002 in lll_mutex_lock_optimized (mutex=0x563595e8f6a8 <fil_system+40>) at ./nptl/pthread_mutex_lock.c:48
 
#3  ___pthread_mutex_lock (mutex=mutex@entry=0x563595e8f6a8 <fil_system+40>) at ./nptl/pthread_mutex_lock.c:93
 
#4  0x00005635944fee75 in psi_mutex_lock (that=0x563595e8f6a8 <fil_system+40>, file=<optimized out>, line=<optimized out>) at ./mysys/my_thr_init.c:489
 
#5  0x00005635944f35fb in inline_mysql_mutex_lock (src_line=1496, src_file=0x563594f91ec8 "./storage/innobase/fil/fil0fil.cc", that=0x563595e8f6a8 <fil_system+40>) at ./include/mysql/psi/mysql_thread.h:746
 
#6  fil_space_t::get (id=0) at ./storage/innobase/fil/fil0fil.cc:1496
 
#7  0x0000563594c49fe6 in buf_read_page (page_id=page_id@entry=..., zip_size=zip_size@entry=0) at ./storage/innobase/include/buf0types.h:131
 
#8  0x00005635945493a7 in buf_page_get_low (page_id=..., zip_size=0, rw_latch=1, guess=0x0, mode=10, mtr=0x7f9a5d958230, err=0x7f9a5d95782c, allow_ibuf_merge=false) at ./storage/innobase/buf/buf0buf.cc:2520
 
#9  0x0000563594c27a6c in btr_cur_t::search_leaf (this=this@entry=0x7f9a5d957ee0, tuple=<optimized out>, mode=mode@entry=PAGE_CUR_GE, latch_mode=BTR_SEARCH_LEAF, mtr=mtr@entry=0x7f9a5d958230) at ./storage/innobase/btr/btr0cur.cc:1174
 
#10 0x0000563594b682d3 in btr_pcur_open (mtr=<optimized out>, cursor=0x7f9a5d957ee0, latch_mode=<optimized out>, mode=PAGE_CUR_GE, tuple=<optimized out>) at ./storage/innobase/include/btr0pcur.h:431
 
#11 btr_pcur_open_on_user_rec (tuple=<optimized out>, latch_mode=<optimized out>, cursor=0x7f9a5d957ee0, mtr=0x7f9a5d958230) at ./storage/innobase/include/btr0pcur.h:449
 
#12 0x0000563594c61347 in dict_load_table_one (name=..., ignore_err=<optimized out>, fk_tables=...) at ./storage/innobase/dict/dict0load.cc:2350
 
#13 0x0000563594c62742 in dict_sys_t::load_table (this=this@entry=0x563595548540 <dict_sys>, name=..., ignore=ignore@entry=DICT_ERR_IGNORE_FK_NOKEY) at ./storage/innobase/dict/dict0load.cc:2552
 
#14 0x0000563594c56ce1 in dict_table_open_on_name (table_name=table_name@entry=0x7f9a5d958e20 "A/B", dict_locked=dict_locked@entry=false, ignore_err=ignore_err@entry=DICT_ERR_IGNORE_FK_NOKEY) at ./storage/innobase/dict/dict0dict.cc:1055
 
#15 0x0000563594b33906 in ha_innobase::open_dict_table (ignore_err=DICT_ERR_IGNORE_FK_NOKEY, is_partition=false, norm_name=0x7f9a5d958e20 "A/B") at ./storage/innobase/handler/ha_innodb.cc:6244
 
#16 ha_innobase::open (this=0x7f9a3c01ecb0, name=0x7f9a3c0244d8 "./A/B") at ./storage/innobase/handler/ha_innodb.cc:5963

The culprit for the hang may be something related to the lock-free hash table that the performance_schema instrumentation is using, causing it to end in an infinite loop. We have an open bug MDEV-28430 in that area, but I see that you are using a processor that uses the AMD64 ISA and therefore should not be affected by that particular bug.

That said, it could be worth investigating if we could protect the closing and opening of InnoDB file handles with fil_space_t::latch instead of using fil_system.mutex. I had been under the impression that opening file handles is relatively fast, but MDEV-32027 recently taught me otherwise. If we improved that in InnoDB (in a separate ticket), I think that the server could still hang, but not block so many other threads.

Comment by Marko Mäkelä [ 2024-02-02 ]

I filed MDEV-33360 for the InnoDB performance improvement. I don’t think that implementing it would prevent hangs due to this bug; it would only make them harder to reproduce.

Generated at Thu Feb 08 10:38:18 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.