Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-29273

Race condition between drop table and encryption thread

    XMLWordPrintable

    Details

      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}
      
      

        Attachments

          Activity

            People

            Assignee:
            thiru Thirunarayanan Balathandayuthapani
            Reporter:
            thiru Thirunarayanan Balathandayuthapani
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start 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.