[MDEV-29273] Race condition between drop table and encryption thread Created: 2022-08-08  Updated: 2023-04-18  Resolved: 2023-04-12

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.5.7, 10.6
Fix Version/s: 11.1.1, 10.11.3, 10.6.13, 10.8.8, 10.10.4

Type: Bug Priority: Major
Reporter: Thirunarayanan Balathandayuthapani Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: rr-profile-analyzed


 Description   

InnoDB throws the following error:

2022-08-08 11:24:29 13 [ERROR] InnoDB: Operating system error number 9 in a file operation.
2022-08-08 11:24:29 13 [ERROR] InnoDB: Error number 9 means 'Bad file descriptor'
2022-08-08 11:24:29 13 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
2022-08-08 11:24:29 13 [ERROR] InnoDB: File (unknown): 'close' returned OS error 209. Cannot continue operation
220808 11:24:29 [ERROR] mysqld got signal 6 ;

This issue caused by race condition between drop thread and fil_encrypt_thread.
fil_encrypt_thread closes the tablespace if the number of opened files exceeds
innodb_open_files. fil_node_open_file() closes the tablespace which are open
and it doesn't have pending operations space->try_to_close(). At that time,
InnoDB drop (is in mtr_t::commit_files) tries to write the redo log for
the file delete operation.

DDL is trying to close the tablespace after encryption threads closes the tablespace
in background.

Encryption thread:
==================

 
Thread 11 hit Breakpoint 4, fil_space_t::set_closing (
    this=0x2f157c5d18a8)
    at /home/mariadb/error9/10.6/storage/innobase/include/fil0fil.h:635
635	    return n_pending.fetch_or(CLOSING, std::memory_order_acquire) &
(rr) p id
$10 = 1427
(rr) p /x n_pending
$6 = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 0x4, 
    _M_i = 0x80000000}, <No data fields>}
(rr) where
#0  fil_space_t::set_closing (this=0x2f157c5d18a8)
    at /home/mariadb/error9/10.6/storage/innobase/include/fil0fil.h:635
#1  0x000056421354b284 in fil_space_t::try_to_close (print_info=false)
    at /home/mariadb/error9/10.6/storage/innobase/fil/fil0fil.cc:103
#2  0x000056421354c1d8 in fil_node_open_file (node=0x2f157c1afc38)
    at /home/mariadb/error9/10.6/storage/innobase/fil/fil0fil.cc:425
#3  0x000056421354d3a8 in fil_space_t::prepare_acquired (
    this=0x2f157c2b4a18)
    at /home/mariadb/error9/10.6/storage/innobase/fil/fil0fil.cc:659
#4  0x0000564213563aa7 in fil_space_t::acquire_if_not_stopped (
    this=0x2f157c2b4a18)
    at /home/mariadb/error9/10.6/storage/innobase/fil/fil0crypt.cc:1345
#5  0x0000564213563dc9 in fil_system_t::default_encrypt_next (
    this=0x564214fb3e40 <fil_system>, space=0x2f157c2b4a18, 
    recheck=false, encrypt=true)
    at /home/mariadb/error9/10.6/storage/innobase/fil/fil0crypt.cc:1411
#6  0x0000564213560529 in fil_space_t::next (space=..., recheck=false, 
    encrypt=true)
    at /home/mariadb/error9/10.6/storage/innobase/fil/fil0crypt.cc:1438
#7  0x0000564213560a47 in fil_crypt_find_space_to_rotate (
    key_state=0x3d626e757be4, state=0x3d626e757bf0, 
    recheck=0x3d626e757bd7)
    at /home/mariadb/error9/10.6/storage/innobase/fil/fil0crypt.cc:1535
#8  0x0000564213562261 in fil_crypt_thread ()
    at /home/mariadb/error9/10.6/storage/innobase/fil/fil0crypt.cc:2034
#9  0x00005642134e63fa in std::__invoke_impl<void, void (*)()> (
    __f=@0x5642170f56d8: 0x564213562176 <fil_crypt_thread()>)
    at /usr/include/c++/7/bits/invoke.h:60
#10 0x00005642134e6101 in std::__invoke<void (*)()> (
    __fn=@0x5642170f56d8: 0x564213562176 <fil_crypt_thread()>)
    at /usr/include/c++/7/bits/invoke.h:95
#11 0x00005642134e6978 in std::thread::_Invoker<std::tuple<void (*)()> >::_M_invoke<0ul> (this=0x5642170f56d8) at /usr/include/c++/7/thread:234
#12 0x00005642134e6949 in std::thread::_Invoker<std::tuple<void (*)()> >::operator() (this=0x5642170f56d8) at /usr/include/c++/7/thread:243
#13 0x00005642134e6928 in std::thread::_State_impl<std::thread::_Invoker---Type <return> to continue, or q <return> to quit---
<std::tuple<void (*)()> > >::_M_run (this=0x5642170f56d0)
    at /usr/include/c++/7/thread:186
#14 0x00007ffe63d316df in ?? ()
   from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#15 0x00007f8d2bbed6db in start_thread (arg=0x3d626e758700)
    at pthread_create.c:463
#16 0x000024681c88161f in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
 
(rr) p /x n_pending
$7 = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 0x4, _M_i = 0x80000000}, <No data fields>}
 
 
(rr) f 1
#1  0x000056421354b284 in fil_space_t::try_to_close (print_info=false) at /home/mariadb/error9/10.6/storage/innobase/fil/fil0fil.cc:103
103	    if (const auto n= space.set_closing())
(rr) p node->name
$9 = 0x2f157c5d1a08 "./test/tmp27.ibd"
 
After set_closing():
====================
(rr) p/x space->n_pending
$12 = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 0x4, _M_i = 0xc0000000}, <No data fields>}

Drop table thread:
==============

 
(rr) t 2
[Switching to thread 2 (Thread 51839.51932)]
#0  0x0000000070000002 in syscall_traced ()
(rr) where
#0  0x0000000070000002 in syscall_traced ()
#1  0x00007f8d2c2451a4 in _raw_syscall () at /home/roc/rr/rr/src/preload/raw_syscall.S:120
#2  0x00007f8d2c2402ce in traced_raw_syscall (call=<optimized out>) at /home/roc/rr/rr/src/preload/syscallbuf.c:278
#3  0x00007f8d2c2440d3 in syscall_hook_internal (call=0x7f8d287d1fa0) at /home/roc/rr/rr/src/preload/syscallbuf.c:3420
#4  syscall_hook (call=0x7f8d287d1fa0) at /home/roc/rr/rr/src/preload/syscallbuf.c:3454
#5  0x00007f8d2c2400b0 in _syscall_hook_trampoline () at /home/roc/rr/rr/src/preload/syscall_hook.S:313
#6  0x00007f8d2c24010f in __morestack () at /home/roc/rr/rr/src/preload/syscall_hook.S:458
#7  0x00007f8d2c24012b in _syscall_hook_trampoline_48_3d_00_f0_ff_ff () at /home/roc/rr/rr/src/preload/syscall_hook.S:477
#8  0x000024681c876fcd in fdatasync (fd=9) at ../sysdeps/unix/sysv/linux/fdatasync.c:28
#9  0x00005642132eca40 in os_file_sync_posix (file=9) at /home/mariadb/error9/10.6/storage/innobase/os/os0file.cc:839
#10 0x00005642132ecdc5 in os_file_flush_func (file=9) at /home/mariadb/error9/10.6/storage/innobase/os/os0file.cc:924
#11 0x00005642132a6bd4 in pfs_os_file_flush_func (file=..., src_file=0x564213c0f5d0 "/home/mariadb/error9/10.6/storage/innobase/log/log0log.cc", 
    src_line=289) at /home/mariadb/error9/10.6/storage/innobase/include/os0file.inl:347
#12 0x00005642132a809d in file_os_io::flush (this=0x564216fefb90) at /home/mariadb/error9/10.6/storage/innobase/log/log0log.cc:289
#13 0x00005642132a8567 in log_file_t::flush (this=0x564214f74060 <log_sys+480>) at /home/mariadb/error9/10.6/storage/innobase/log/log0log.cc:463
#14 0x00005642132a8d8b in log_t::file::flush (this=0x564214f74040 <log_sys+448>) at /home/mariadb/error9/10.6/storage/innobase/log/log0log.cc:530
#15 0x00005642132a9631 in log_write_flush_to_disk_low (lsn=6903017) at /home/mariadb/error9/10.6/storage/innobase/log/log0log.cc:649
#16 0x00005642132aa3fe in log_write_and_flush () at /home/mariadb/error9/10.6/storage/innobase/log/log0log.cc:903
#17 0x00005642132ded03 in mtr_t::commit_file (this=0x7f8d2c571f20, space=..., name=0x0)
    at /home/mariadb/error9/10.6/storage/innobase/mtr/mtr0mtr.cc:660
#18 0x0000564213551506 in fil_delete_tablespace (id=1427) at /home/mariadb/error9/10.6/storage/innobase/fil/fil0fil.cc:1651
#19 0x0000564213545e54 in trx_t::commit (this=0x4d933b25cb80, deleted=std::vector of length 0, capacity 0)
    at /home/mariadb/error9/10.6/storage/innobase/dict/drop.cc:274
#20 0x00005642131eac35 in ha_innobase::delete_table (this=0x2f157cdfc248, name=0x7f8d2c573460 "./test/tmp27")
    at /home/mariadb/error9/10.6/storage/innobase/handler/ha_innodb.cc:13757
#21 0x0000564212d81099 in hton_drop_table (hton=0x564216bde128, path=0x7f8d2c573460 "./test/tmp27")
    at /home/mariadb/error9/10.6/sql/handler.cc:576
#22 0x0000564212d87453 in ha_delete_table (thd=0x2f157c000d78, hton=0x564216bde128, path=0x7f8d2c573460 "./test/tmp27", db=0x2f157c016c88, 
    alias=0x2f157c016c98, generate_warning=false) at /home/mariadb/error9/10.6/sql/handler.cc:3121
#23 0x0000564212add0ca in quick_rm_table (thd=0x2f157c000d78, base=0x564216bde128, db=0x2f157c016c88, table_name=0x2f157c016c98, flags=0, 
    table_path=0x0) at /home/mariadb/error9/10.6/sql/sql_table.cc:1912
#24 0x000056421293b197 in drop_open_table (thd=0x2f157c000d78, table=0x2f157cdf91a8, db_name=0x2f157c016c88, table_name=0x2f157c016c98)
    at /home/mariadb/error9/10.6/sql/sql_base.cc:1396
#25 0x00005642129a5cd9 in select_create::abort_result_set (this=0x2f157c019d98) at /home/mariadb/error9/10.6/sql/sql_insert.cc:5224
#26 0x0000564212a33845 in handle_select (thd=0x2f157c000d78, lex=0x2f157c005018, result=0x2f157c019d98, setup_tables_done_option=0)
    at /home/mariadb/error9/10.6/sql/sql_select.cc:572
---Type <return> to continue, or q <return> to quit---
#27 0x0000564212afb439 in Sql_cmd_create_table_like::execute (this=0x2f157c016c10, thd=0x2f157c000d78)
    at /home/mariadb/error9/10.6/sql/sql_table.cc:11810
#28 0x00005642129f3442 in mysql_execute_command (thd=0x2f157c000d78, is_called_from_prepared_stmt=false)
    at /home/mariadb/error9/10.6/sql/sql_parse.cc:5997
#29 0x00005642129f94f8 in mysql_parse (thd=0x2f157c000d78, 
    rawbuf=0x2f157c0167a0 "CREATE /* QNO 996 CON_ID 13 */ TABLE tmp27 AS /* `table10_innodb_int_autoinc` */ SELECT DISTINCT BIT_OR( NULL ) AS field1 FROM table10_innodb_int_autoinc GROUP BY /* VALUES( `col_varchar_355_utf8_full"..., length=520, parser_state=0x7f8d2c5743c0)
    at /home/mariadb/error9/10.6/sql/sql_parse.cc:8030
#30 0x00005642129e5987 in dispatch_command (command=COM_QUERY, thd=0x2f157c000d78, 
    packet=0x2f157c00b729 "CREATE /* QNO 996 CON_ID 13 */ TABLE tmp27 AS /* `table10_innodb_int_autoinc` */ SELECT DISTINCT BIT_OR( NULL ) AS field1 FROM table10_innodb_int_autoinc GROUP BY /* VALUES( `col_varchar_355_utf8_full"..., packet_length=521, blocking=true)
    at /home/mariadb/error9/10.6/sql/sql_parse.cc:1896
#31 0x00005642129e4295 in do_command (thd=0x2f157c000d78, blocking=true) at /home/mariadb/error9/10.6/sql/sql_parse.cc:1409
#32 0x0000564212b9f6d5 in do_handle_one_connection (connect=0x56421710f9a8, put_in_cache=true)
    at /home/mariadb/error9/10.6/sql/sql_connect.cc:1418
#33 0x0000564212b9f370 in handle_one_connection (arg=0x56421720dcf8) at /home/mariadb/error9/10.6/sql/sql_connect.cc:1312
#34 0x0000564213101ae3 in pfs_spawn_thread (arg=0x564216bce4f8) at /home/mariadb/error9/10.6/storage/perfschema/pfs.cc:2201
#35 0x00007f8d2bbed6db in start_thread (arg=0x7f8d2c575700) at pthread_create.c:463
#36 0x000024681c88161f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
 
(rr) p space->id
$13 = 1427
(rr) p *(fil_node_t*) space->chain->start
$14 = {space = 0x2f157c5d18a8, name = 0x2f157c5d1a08 "./test/tmp27.ibd", handle = {m_file = 299, m_psi = 0x0}, on_ssd = 0, punch_hole = 0, 
  atomic_write = 0, is_raw_disk = 0, deferred = 0, size = 6, init_size = 4, max_size = 4294967295, being_extended = {m = {_M_base = {
        static _S_alignment = 1, _M_i = false}}}, chain = {prev = 0x0, next = 0x0}, block_size = 4096}



 Comments   
Comment by Marko Mäkelä [ 2023-04-05 ]

We’d better use a single atomic operation to manipulate the field. Can you please change the definition of fil_space_t::set_closing() so that it will not mask any flags, and adjust all its callers?

diff --git a/storage/innobase/include/fil0fil.h b/storage/innobase/include/fil0fil.h
index ff6ece8a360..f878598faf7 100644
--- a/storage/innobase/include/fil0fil.h
+++ b/storage/innobase/include/fil0fil.h
@@ -625,11 +625,10 @@ struct fil_space_t final
 private:
   MY_ATTRIBUTE((warn_unused_result))
   /** Prepare to close the file handle.
-  @return number of pending operations, possibly with NEEDS_FSYNC flag */
+  @return number of pending operations, possibly with flags */
   uint32_t set_closing()
   {
-    return n_pending.fetch_or(CLOSING, std::memory_order_acquire) &
-      (PENDING | NEEDS_FSYNC);
+    return n_pending.fetch_or(CLOSING, std::memory_order_acquire);
   }
 
 public:

Comment by Matthias Leich [ 2023-04-12 ]

origin/bb-10.6-MDEV-29273 95cd70fa3d91e87b4a50d1737440a950cff40ea1 2023-04-05T16:55:07+05:30
performed well in RQG testing. The issues observed are in other trees too.

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