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

InnoDB: Failing assertion: table->get_ref_count() == 0 upon ALTER TABLE ... MODIFY COLUMN

Details

    Description

      origin/10.6 8d742fe4acb91652fcbeb36506d20ead4ff19e83 2022-02-01T19:50:08+05:30
      compiled with debug
       
      # 2022-02-08T13:09:59 [3414940] | [rr 3417576 1062259]2022-02-08 12:59:14 0x7ffe91d1d700[rr 3417576 1062262]  InnoDB: Assertion failure in file /data/Server/10.6/storage/innobase/dict/dict0dict.cc line 1824
      # 2022-02-08T13:09:59 [3414940] | [rr 3417576 1062264]InnoDB: Failing assertion: table->get_ref_count() == 0
      Query: ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text
      # 2022-02-08T13:09:59 [3414940] | [rr 3417576 1083366]Status: KILL_TIMEOUT
       
      (rr) bt
      #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
      #1  0x000072951fbf3859 in __GI_abort () at abort.c:79
      #2  0x000055d44cf52045 in ut_dbg_assertion_failed (expr=0x55d44e1ad3a0 "table->get_ref_count() == 0", file=0x55d44e1ad660 "/data/Server/10.6/storage/innobase/dict/dict0dict.cc", line=1824)
          at /data/Server/10.6/storage/innobase/ut/ut0dbg.cc:60
      #3  0x000055d44d09c2ec in dict_sys_t::remove (this=0x55d44f09f280 <dict_sys>, table=0x6180001cf508, lru=false, keep=false) at /data/Server/10.6/storage/innobase/dict/dict0dict.cc:1824
      #4  0x000055d44d118db3 in trx_t::commit (this=0x6fd74f72c1c8, deleted=std::vector of length 17, capacity 32 = {...}) at /data/Server/10.6/storage/innobase/dict/drop.cc:249
      #5  0x000055d44ca7bb92 in ha_innobase::delete_table (this=0x62b00015ba00, name=0x7ffe91d17380 "./test/#sql-backup-3425e8-37") at /data/Server/10.6/storage/innobase/handler/ha_innodb.cc:13636
      #6  0x000055d44c15fc5c in hton_drop_table (hton=0x615000002118, path=0x7ffe91d17380 "./test/#sql-backup-3425e8-37") at /data/Server/10.6/sql/handler.cc:576
      #7  0x000055d44c16c57b in ha_delete_table (thd=0x62b000150218, hton=0x615000002118, path=0x7ffe91d17380 "./test/#sql-backup-3425e8-37", db=0x7ffe91d191b0, alias=0x7ffe91d17890, generate_warning=false)
          at /data/Server/10.6/sql/handler.cc:3100
      #8  0x000055d44bbd5efc in quick_rm_table (thd=0x62b000150218, base=0x615000002118, db=0x7ffe91d191b0, table_name=0x7ffe91d17890, flags=3, table_path=0x0) at /data/Server/10.6/sql/sql_table.cc:1919
      #9  0x000055d44bc11f1f in mysql_alter_table (thd=0x62b000150218, new_db=0x62b000154c18, new_name=0x62b000155030, create_info=0x7ffe91d1a650, table_list=0x62b0001573d0, alter_info=0x7ffe91d1a520, order_num=0, order=0x0, 
          ignore=false, if_exists=false) at /data/Server/10.6/sql/sql_table.cc:10659
      #10 0x000055d44bd9cc3e in Sql_cmd_alter_table::execute (this=0x62b000157c08, thd=0x62b000150218) at /data/Server/10.6/sql/sql_alter.cc:542
      #11 0x000055d44b9a0fe0 in mysql_execute_command (thd=0x62b000150218, is_called_from_prepared_stmt=false) at /data/Server/10.6/sql/sql_parse.cc:5996
      #12 0x000055d44b9ad3c8 in mysql_parse (thd=0x62b000150218, rawbuf=0x62b000157238 "ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text /* E_R Thread1 QNO 1142 CON_ID 55 */", length=96, 
          parser_state=0x7ffe91d1bb20) at /data/Server/10.6/sql/sql_parse.cc:8029
      #13 0x000055d44b98576d in dispatch_command (command=COM_QUERY, thd=0x62b000150218, packet=0x629000c8a219 " ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text /* E_R Thread1 QNO 1142 CON_ID 55 */ ", 
          packet_length=98, blocking=true) at /data/Server/10.6/sql/sql_parse.cc:1896
      #14 0x000055d44b982b45 in do_command (thd=0x62b000150218, blocking=true) at /data/Server/10.6/sql/sql_parse.cc:1404
      #15 0x000055d44bd83074 in do_handle_one_connection (connect=0x608000045b38, put_in_cache=true) at /data/Server/10.6/sql/sql_connect.cc:1418
      #16 0x000055d44bd82900 in handle_one_connection (arg=0x608000003638) at /data/Server/10.6/sql/sql_connect.cc:1312
      #17 0x00004005048e9609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #18 0x000072951fcf0293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      (rr)
      sdp:/data/results/1644351887/TBR-1069/dev/shm/rqg/1644351887/236/1/rr
       
      RQG
      ===
      # git clone https://github.com/mleich1/rqg --branch experimental RQG
      #
      # GIT_SHOW: HEAD -> experimental, origin/experimental 3dd8aeba1eee7ed7334e5e925f71f0c6eb70a7f4 2022-02-08T15:24:56+01:00
      # rqg.pl  : Version 4.0.4 (2021-12)
      #
      # $RQG_HOME/rqg.pl \
      # --duration=300 \
      # --queries=10000000 \
      # --no_mask \
      # --seed=random \
      # --max_gd_duration=1200 \
      # --engine=InnoDB \
      # --gendata_sql=conf/mariadb/table_stress.sql \
      # --gendata=conf/mariadb/table_stress.zz \
      # --rpl_mode=none \
      # --mysqld=--loose-innodb_read_only_compressed=OFF \
      # --mysqld=--connect_timeout=60 \
      # --mysqld=--log_bin_trust_function_creators=1 \
      # --mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
      # --mysqld=--loose-idle_transaction_timeout=0 \
      # --mysqld=--log-output=none \
      # --mysqld=--file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
      # --mysqld=--loose-idle_write_transaction_timeout=0 \
      # --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
      # --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
      # --mysqld=--net_read_timeout=30 \
      # --mysqld=--innodb-buffer-pool-size=5M \
      # --mysqld=--loose-table_lock_wait_timeout=50 \
      # --mysqld=--innodb_page_size=4K \
      # --mysqld=--sync-binlog=1 \
      # --mysqld=--lock-wait-timeout=86400 \
      # --mysqld=--innodb-lock-wait-timeout=50 \
      # --mysqld=--innodb_purge_rseg_truncate_frequency=2 \
      # --mysqld=--log-bin \
      # --mysqld=--loose-max-statement-time=30 \
      # --mysqld=--net_write_timeout=60 \
      # --mysqld=--plugin-load-add=file_key_management.so \
      # --mysqld=--wait_timeout=28800 \
      # --mysqld=--interactive_timeout=28800 \
      # --mysqld=--slave_net_timeout=60 \
      # --mysqld=--loose-plugin-load-add=provider_lz4.so \
      # --mysqld=--loose-idle_readonly_transaction_timeout=0 \
      # --reporters=Backtrace,Deadlock1,ErrorLog \
      # --validators=None \
      # --grammar=/data/results/1644351887/c00000.yy \
      # --threads=5 \
      # <local settings>
      
      

      Attachments

        1. c00000.yy
          8 kB
        2. rqg.log
          7.06 MB
        3. simp_mix_table_stress_innodb_dml1.cfg
          47 kB

        Issue Links

          Activity

            mleich Matthias Leich added a comment - - edited

            c00000.yy is a simplified derivate of conf/mariadb/table_stress_innodb_dml.yy.
            simp_mix_table_stress_innodb_dml1.cfg was used during test simplification and bug replay.
             
            Error pattern for RQG
            [ 'TBR-1069-ExMDEV-27017', 'InnoDB: Assertion failure in file .{1,200}dict0dict.cc line.+InnoDB: Failing assertion: table->get_ref_count\(\) == 0.+RESULT: The RQG run ended with status STATUS_SERVER_CRASHED' ],
            

            mleich Matthias Leich added a comment - - edited c00000.yy is a simplified derivate of conf/mariadb/table_stress_innodb_dml.yy. simp_mix_table_stress_innodb_dml1.cfg was used during test simplification and bug replay.   Error pattern for RQG [ 'TBR-1069-ExMDEV-27017', 'InnoDB: Assertion failure in file .{1,200}dict0dict.cc line.+InnoDB: Failing assertion: table->get_ref_count\(\) == 0.+RESULT: The RQG run ended with status STATUS_SERVER_CRASHED' ],

            Thread 3:
            (rr) where
            #0  ha_innobase::delete_table (this=0x62b00015ba00, name=0x7ffe91d17380 "./test/#sql-backup-3425e8-37")
                at /data/Server/10.6/storage/innobase/handler/ha_innodb.cc:13459
            #1  0x000055d44c15fc5c in hton_drop_table (hton=0x615000002118, path=0x7ffe91d17380 "./test/#sql-backup-3425e8-37")
                at /data/Server/10.6/sql/handler.cc:576
            #2  0x000055d44c16c57b in ha_delete_table (thd=0x62b000150218, hton=0x615000002118, path=0x7ffe91d17380 "./test/#sql-backup-3425e8-37", 
                db=0x7ffe91d191b0, alias=0x7ffe91d17890, generate_warning=false) at /data/Server/10.6/sql/handler.cc:3100
            #3  0x000055d44bbd5efc in quick_rm_table (thd=0x62b000150218, base=0x615000002118, db=0x7ffe91d191b0, table_name=0x7ffe91d17890, flags=3, 
                table_path=0x0) at /data/Server/10.6/sql/sql_table.cc:1919
            #4  0x000055d44bc11f1f in mysql_alter_table (thd=0x62b000150218, new_db=0x62b000154c18, new_name=0x62b000155030, create_info=0x7ffe91d1a650, 
                table_list=0x62b0001573d0, alter_info=0x7ffe91d1a520, order_num=0, order=0x0, ignore=false, if_exists=false)
                at /data/Server/10.6/sql/sql_table.cc:10659
            #5  0x000055d44bd9cc3e in Sql_cmd_alter_table::execute (this=0x62b000157c08, thd=0x62b000150218) at /data/Server/10.6/sql/sql_alter.cc:542
            #6  0x000055d44b9a0fe0 in mysql_execute_command (thd=0x62b000150218, is_called_from_prepared_stmt=false)
                at /data/Server/10.6/sql/sql_parse.cc:5996
            #7  0x000055d44b9ad3c8 in mysql_parse (thd=0x62b000150218, 
                rawbuf=0x62b000157238 "ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text /* E_R Thread1 QNO 1142 CON_ID 55 */", length=96, 
                parser_state=0x7ffe91d1bb20) at /data/Server/10.6/sql/sql_parse.cc:8029
            #8  0x000055d44b98576d in dispatch_command (command=COM_QUERY, thd=0x62b000150218, 
                packet=0x629000c8a219 " ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text /* E_R Thread1 QNO 1142 CON_ID 55 */ ", 
                packet_length=98, blocking=true) at /data/Server/10.6/sql/sql_parse.cc:1896
            #9  0x000055d44b982b45 in do_command (thd=0x62b000150218, blocking=true) at /data/Server/10.6/sql/sql_parse.cc:1404
            #10 0x000055d44bd83074 in do_handle_one_connection (connect=0x608000045b38, put_in_cache=true) at /data/Server/10.6/sql/sql_connect.cc:1418
            #11 0x000055d44bd82900 in handle_one_connection (arg=0x608000003638) at /data/Server/10.6/sql/sql_connect.cc:1312
            #12 0x00004005048e9609 in start_thread (arg=<optimized out>) at pthread_create.c:477
            #13 0x000072951fcf0293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
             
            thread 26:
            (rr) where
            #0  0x000055d44cbf7d74 in dict_sys_t::find_table (this=0x55d44f09f280 <dict_sys>, id=671)
                at /data/Server/10.6/storage/innobase/include/dict0dict.h:1470
            #1  0x000055d44d09580f in dict_table_open_on_id (table_id=671, dict_locked=false, table_op=DICT_TABLE_OP_NORMAL, thd=0x62b000023218, 
                mdl=0x61a00000aaa8) at /data/Server/10.6/storage/innobase/dict/dict0dict.cc:836
            #2  0x000055d44ce2be08 in row_purge_parse_undo_rec (node=0x61a00000a908, undo_rec=0x621000abe3d8 "", thr=0x616000058cc0, 
                updated_extern=0x10b27ab59820) at /data/Server/10.6/storage/innobase/row/row0purge.cc:1028
            #3  0x000055d44ce2d6ba in row_purge (node=0x61a00000a908, undo_rec=0x621000abe3d8 "", thr=0x616000058cc0)
                at /data/Server/10.6/storage/innobase/row/row0purge.cc:1206
            #4  0x000055d44ce2db08 in row_purge_step (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/row/row0purge.cc:1258
            #5  0x000055d44cd1ee45 in que_thr_step (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/que/que0que.cc:653
            #6  0x000055d44cd1f1ed in que_run_threads_low (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/que/que0que.cc:709
            #7  0x000055d44cd1f38f in que_run_threads (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/que/que0que.cc:729
            #8  0x000055d44ceabaa7 in srv_task_execute () at /data/Server/10.6/storage/innobase/srv/srv0srv.cc:1716
            

            Purge thread is waiting at dict_table_open_on_id() after checking check_stop_FTS() and at that time, InnoDB ddl does stop_FTS() ,
            make sure that fts table doesn't have any other ref count. So there is still race condition can occur between purge thread and DDL.

            thiru Thirunarayanan Balathandayuthapani added a comment - Thread 3: (rr) where #0 ha_innobase::delete_table (this=0x62b00015ba00, name=0x7ffe91d17380 "./test/#sql-backup-3425e8-37") at /data/Server/10.6/storage/innobase/handler/ha_innodb.cc:13459 #1 0x000055d44c15fc5c in hton_drop_table (hton=0x615000002118, path=0x7ffe91d17380 "./test/#sql-backup-3425e8-37") at /data/Server/10.6/sql/handler.cc:576 #2 0x000055d44c16c57b in ha_delete_table (thd=0x62b000150218, hton=0x615000002118, path=0x7ffe91d17380 "./test/#sql-backup-3425e8-37", db=0x7ffe91d191b0, alias=0x7ffe91d17890, generate_warning=false) at /data/Server/10.6/sql/handler.cc:3100 #3 0x000055d44bbd5efc in quick_rm_table (thd=0x62b000150218, base=0x615000002118, db=0x7ffe91d191b0, table_name=0x7ffe91d17890, flags=3, table_path=0x0) at /data/Server/10.6/sql/sql_table.cc:1919 #4 0x000055d44bc11f1f in mysql_alter_table (thd=0x62b000150218, new_db=0x62b000154c18, new_name=0x62b000155030, create_info=0x7ffe91d1a650, table_list=0x62b0001573d0, alter_info=0x7ffe91d1a520, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/Server/10.6/sql/sql_table.cc:10659 #5 0x000055d44bd9cc3e in Sql_cmd_alter_table::execute (this=0x62b000157c08, thd=0x62b000150218) at /data/Server/10.6/sql/sql_alter.cc:542 #6 0x000055d44b9a0fe0 in mysql_execute_command (thd=0x62b000150218, is_called_from_prepared_stmt=false) at /data/Server/10.6/sql/sql_parse.cc:5996 #7 0x000055d44b9ad3c8 in mysql_parse (thd=0x62b000150218, rawbuf=0x62b000157238 "ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text /* E_R Thread1 QNO 1142 CON_ID 55 */", length=96, parser_state=0x7ffe91d1bb20) at /data/Server/10.6/sql/sql_parse.cc:8029 #8 0x000055d44b98576d in dispatch_command (command=COM_QUERY, thd=0x62b000150218, packet=0x629000c8a219 " ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text /* E_R Thread1 QNO 1142 CON_ID 55 */ ", packet_length=98, blocking=true) at /data/Server/10.6/sql/sql_parse.cc:1896 #9 0x000055d44b982b45 in do_command (thd=0x62b000150218, blocking=true) at /data/Server/10.6/sql/sql_parse.cc:1404 #10 0x000055d44bd83074 in do_handle_one_connection (connect=0x608000045b38, put_in_cache=true) at /data/Server/10.6/sql/sql_connect.cc:1418 #11 0x000055d44bd82900 in handle_one_connection (arg=0x608000003638) at /data/Server/10.6/sql/sql_connect.cc:1312 #12 0x00004005048e9609 in start_thread (arg=<optimized out>) at pthread_create.c:477 #13 0x000072951fcf0293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95   thread 26: (rr) where #0 0x000055d44cbf7d74 in dict_sys_t::find_table (this=0x55d44f09f280 <dict_sys>, id=671) at /data/Server/10.6/storage/innobase/include/dict0dict.h:1470 #1 0x000055d44d09580f in dict_table_open_on_id (table_id=671, dict_locked=false, table_op=DICT_TABLE_OP_NORMAL, thd=0x62b000023218, mdl=0x61a00000aaa8) at /data/Server/10.6/storage/innobase/dict/dict0dict.cc:836 #2 0x000055d44ce2be08 in row_purge_parse_undo_rec (node=0x61a00000a908, undo_rec=0x621000abe3d8 "", thr=0x616000058cc0, updated_extern=0x10b27ab59820) at /data/Server/10.6/storage/innobase/row/row0purge.cc:1028 #3 0x000055d44ce2d6ba in row_purge (node=0x61a00000a908, undo_rec=0x621000abe3d8 "", thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/row/row0purge.cc:1206 #4 0x000055d44ce2db08 in row_purge_step (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/row/row0purge.cc:1258 #5 0x000055d44cd1ee45 in que_thr_step (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/que/que0que.cc:653 #6 0x000055d44cd1f1ed in que_run_threads_low (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/que/que0que.cc:709 #7 0x000055d44cd1f38f in que_run_threads (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/que/que0que.cc:729 #8 0x000055d44ceabaa7 in srv_task_execute () at /data/Server/10.6/storage/innobase/srv/srv0srv.cc:1716 Purge thread is waiting at dict_table_open_on_id() after checking check_stop_FTS() and at that time, InnoDB ddl does stop_FTS() , make sure that fts table doesn't have any other ref count. So there is still race condition can occur between purge thread and DDL.

            I think that we must make dict_table_open_on_id() in row_purge_parse_undo_rec() avoid table->acquire() if purge_sys.must_wait_FTS() holds. Also, purge_sys_t::stop_FTS() must be protected by exclusive dict_sys.latch to avoid a race between those functions.

            marko Marko Mäkelä added a comment - I think that we must make dict_table_open_on_id() in row_purge_parse_undo_rec() avoid table->acquire() if purge_sys.must_wait_FTS() holds. Also, purge_sys_t::stop_FTS() must be protected by exclusive dict_sys.latch to avoid a race between those functions.

            origin/bb-10.6-MDEV-27783 27b0030b9dc48d1e5264d084e4a917700271c8ab 2022-04-07T10:32:51+05:30
            behaved well in RQG testing. The problems hit are either already known or not specific to the MDEV.
            

            mleich Matthias Leich added a comment - origin/bb-10.6-MDEV-27783 27b0030b9dc48d1e5264d084e4a917700271c8ab 2022-04-07T10:32:51+05:30 behaved well in RQG testing. The problems hit are either already known or not specific to the MDEV.

            People

              thiru Thirunarayanan Balathandayuthapani
              mleich Matthias Leich
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.