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

Potential hang in purge when virtual indexed columns exist

    XMLWordPrintable

    Details

      Description

      Scenario:
      1. Start the server and generate some initial data
      2. Two sessions run their usual DDL/DML battle
      3. SIGKILL server during 2. is ongoing
      4. Restart attempt with success
      5. OPTIMIZE TABLE harvests a server crash
      mysqld: /data/Server/bb-10.6-monty-innodb_C/storage/innobase/include/sux_lock.h:347: void sux_lock<srw>::s_lock() [with srw = ssux_lock_low]: Assertion `!have_s()' failed.
      The server error log dsays
      [rr 1613402 71880]Query (0x0): [rr 1613402 71882](null)[rr 1613402 71884]
      # 2021-05-12T06:43:39 [1504257] | Connection ID (thread ID): 0
      # 2021-05-12T06:43:39 [1504257] | [rr 1613402 71886]Status: NOT_KILLED
       
      #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
      #1  0x00007f852263d859 in __GI_abort () at abort.c:79
      #2  0x00007f852263d729 in __assert_fail_base (fmt=0x7f85227d3588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55fb5dbf9fc0 "!have_s()", file=0x55fb5dbf7600 "/data/Server/bb-10.6-monty-innodb_C/storage/innobase/include/sux_lock.h", 
          line=347, function=<optimized out>) at assert.c:92
      #3  0x00007f852264ef36 in __GI___assert_fail (assertion=assertion@entry=0x55fb5dbf9fc0 "!have_s()", file=file@entry=0x55fb5dbf7600 "/data/Server/bb-10.6-monty-innodb_C/storage/innobase/include/sux_lock.h", line=line@entry=347, 
          function=function@entry=0x55fb5dbf9f60 "void sux_lock<srw>::s_lock() [with srw = ssux_lock_low]") at assert.c:101
      #4  0x000055fb5cae3a3c in sux_lock<ssux_lock_low>::s_lock (this=this@entry=0x7f850e932900) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/include/sux_lock.h:347
      #5  0x000055fb5cad29b1 in mtr_t::page_lock (this=this@entry=0x7f85024d90d0, block=block@entry=0x7f850e932880, rw_latch=rw_latch@entry=1) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/mtr/mtr0mtr.cc:1063
      #6  0x000055fb5cf95fae in buf_page_get_low (page_id=<error reading variable: Cannot access memory at address 0xfffffffffffffd91>, zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=1, guess=<optimized out>, guess@entry=0x0, mode=mode@entry=10, 
          mtr=mtr@entry=0x7f85024d90d0, err=<optimized out>, allow_ibuf_merge=<optimized out>) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/buf/buf0buf.cc:3042
      #7  0x000055fb5cf967bf in buf_page_get_gen (page_id=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=1, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7f85024d90d0, err=0x0, allow_ibuf_merge=false)
          at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/buf/buf0buf.cc:3105
      #8  0x000055fb5ce8b4ad in btr_read_autoinc_with_fallback (table=table@entry=0x618000030108, col_no=col_no@entry=0) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/include/buf0types.h:108
      #9  0x000055fb5c870b9d in initialize_auto_increment (table=0x618000030108, field=<optimized out>) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/handler/ha_innodb.cc:5484
      #10 0x000055fb5c892c47 in ha_innobase::open (this=0x61d0000f96b8, name=0x61b000040458 "./test/D") at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/handler/ha_innodb.cc:5731
      #11 0x000055fb5be6059a in handler::ha_open (this=0x61d0000f96b8, table_arg=table_arg@entry=0x619000081b98, name=0x61b000040458 "./test/D", mode=2, test_if_locked=test_if_locked@entry=18, mem_root=mem_root@entry=0x0, partitions_to_open=0x0)
          at /data/Server/bb-10.6-monty-innodb_C/sql/handler.cc:3038
      #12 0x000055fb5b992ead in open_table_from_share (thd=thd@entry=0x62b00009a218, share=share@entry=0x61b00003feb8, alias=alias@entry=0x61c000030900, db_stat=db_stat@entry=33, prgflag=prgflag@entry=8, ha_open_flags=18, outparam=<optimized out>, 
          is_create_table=<optimized out>, partitions_to_open=<optimized out>) at /data/Server/bb-10.6-monty-innodb_C/sql/table.cc:4305
      #13 0x000055fb5b483611 in open_table (thd=thd@entry=0x62b00009a218, table_list=table_list@entry=0x61c0000308b8, ot_ctx=ot_ctx@entry=0x7f85024da360) at /data/Server/bb-10.6-monty-innodb_C/sql/sql_base.cc:2003
      #14 0x000055fb5b4de1cd in open_purge_table (thd=thd@entry=0x62b00009a218, db=db@entry=0x7f85024da490 "test", dblen=<optimized out>, tb=tb@entry=0x7f85024da5a0 "D", tblen=<optimized out>)
          at /data/Server/bb-10.6-monty-innodb_C/sql/sql_class.cc:4749
      #15 0x000055fb5c85a41b in innodb_find_table_for_vc (thd=0x62b00009a218, table=0x618000030108) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/handler/ha_innodb.cc:19616
      #16 0x000055fb5c88614a in innobase_allocate_row_for_vcol (thd=thd@entry=0x62b00009a218, index=index@entry=0x6160020f2c08, heap=heap@entry=0x7f85024da810, table=table@entry=0x7f85024da7d0, storage=storage@entry=0x7f85024da7f0)
          at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/handler/ha_innodb.cc:19756
      #17 0x000055fb5cd5d7f3 in ib_vcol_row::record (table=0x7f85024da7d0, index=0x6160020f2c08, thd=0x62b00009a218, this=0x7f85024da7f0) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/include/row0mysql.h:888
      #18 row_vers_build_clust_v_col (row=row@entry=0x619000080d50, clust_index=clust_index@entry=0x6160020f2008, index=index@entry=0x6160020f2c08, heap=<optimized out>) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/row/row0vers.cc:463
      #19 0x000055fb5cd6f4db in row_vers_old_has_index_entry (also_curr=also_curr@entry=true, rec=<optimized out>, mtr=mtr@entry=0x7f85024dabd0, index=index@entry=0x6160020f2c08, ientry=ientry@entry=0x619000080808, 
          roll_ptr=roll_ptr@entry=14073748868236827, trx_id=<optimized out>) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/row/row0vers.cc:929
      #20 0x000055fb5ccbf4f7 in row_purge_poss_sec (node=node@entry=0x61a000006d08, index=index@entry=0x6160020f2c08, entry=entry@entry=0x619000080808, sec_pcur=sec_pcur@entry=0x7f85024db440, sec_mtr=sec_mtr@entry=0x7f85024db930, 
          is_tree=is_tree@entry=false) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/include/page0cur.ic:91
      #21 0x000055fb5cccf418 in row_purge_remove_sec_if_poss_leaf (node=node@entry=0x61a000006d08, index=index@entry=0x6160020f2c08, entry=entry@entry=0x619000080808) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/row/row0purge.cc:520
      #22 0x000055fb5ccd50bd in row_purge_remove_sec_if_poss (entry=0x619000080808, index=0x6160020f2c08, node=0x61a000006d08) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/row/row0purge.cc:621
      #23 row_purge_del_mark (node=node@entry=0x61a000006d08) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/row/row0purge.cc:691
      #24 0x000055fb5ccd6a9c in row_purge_record_func (node=node@entry=0x61a000006d08, undo_rec=undo_rec@entry=0x621000042588 "", thr=thr@entry=0x6160008563c0, updated_extern=<optimized out>)
          at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/row/row0purge.cc:1124
      #25 0x000055fb5ccd7364 in row_purge (node=node@entry=0x61a000006d08, undo_rec=undo_rec@entry=0x621000042588 "", thr=thr@entry=0x6160008563c0) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/row/row0purge.cc:1185
      #26 0x000055fb5ccd7c97 in row_purge_step (thr=thr@entry=0x6160008563c0) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/row/row0purge.cc:1234
      #27 0x000055fb5cb801de in que_thr_step (thr=thr@entry=0x6160008563c0) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/que/que0que.cc:653
      #28 0x000055fb5cb804da in que_run_threads_low (thr=thr@entry=0x6160008563c0) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/que/que0que.cc:709
      #29 0x000055fb5cb807a6 in que_run_threads (thr=thr@entry=0x6160008563c0) at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/que/que0que.cc:729
      #30 0x000055fb5cd83b96 in srv_task_execute () at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/srv/srv0srv.cc:1812
      #31 0x000055fb5cd83d89 in purge_worker_callback () at /data/Server/bb-10.6-monty-innodb_C/storage/innobase/srv/srv0srv.cc:1975
      #32 0x000055fb5d283076 in tpool::task_group::execute (this=0x55fb5f2d59c0 <purge_task_group>, t=t@entry=0x55fb5f2d5900 <purge_worker_task>) at /data/Server/bb-10.6-monty-innodb_C/tpool/task_group.cc:55
      #33 0x000055fb5d283795 in tpool::task::execute (this=0x55fb5f2d5900 <purge_worker_task>) at /data/Server/bb-10.6-monty-innodb_C/tpool/task.cc:47
      #34 0x000055fb5d27bfbe in tpool::thread_pool_generic::worker_main (this=0x618000000480, thread_var=0x63000001fd00) at /data/Server/bb-10.6-monty-innodb_C/tpool/tpool_generic.cc:546
      #35 0x000055fb5d27ccd8 in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__t=<optimized out>, __f=<optimized out>) at /usr/include/c++/9/bits/invoke.h:89
      #36 std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=<optimized out>) at /usr/include/c++/9/bits/invoke.h:95
      #37 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=<optimized out>) at /usr/include/c++/9/thread:244
      #38 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=<optimized out>) at /usr/include/c++/9/thread:251
      #39 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=<optimized out>) at /usr/include/c++/9/thread:195
      #40 0x00007f8522a4ad84 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
      #41 0x00007f8522b66609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #42 0x00007f852273a293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      (rr)
       
      sdp:/data/Results/1620824721/TBR-1081-MDEV-25664/dev/shm/vardir/1620824721/184/1/rr
      _RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0   # Fate of the server till SIGKILL
      _RR_TRACE_DIR="." rr replay --mark-stdio mysqld-1   # Fate of the server during + after restart
       
      GIT_SHOW: HEAD, origin/bb-10.6-monty-innodb 98ff3177096311914ce10d72df04ad3b7106d0be 2021-05-12T15:11:07+03:00
      Per Marko this problem should affect 10.2 already.
       
      RQG
      ====
      git clone https://github.com/mleich1/rqg --branch experimental RQG
       
      perl rqg.pl \
      --views \
      --grammar=conf/mariadb/partitions_innodb.yy \
      --redefine=conf/mariadb/alter_table.yy \
      --redefine=conf/mariadb/instant_add.yy \
      --redefine=conf/mariadb/modules/alter_table_columns.yy \
      --redefine=conf/mariadb/bulk_insert.yy \
      --redefine=conf/mariadb/modules/foreign_keys.yy \
      --redefine=conf/mariadb/modules/locks.yy \
      --redefine=conf/mariadb/modules/sql_mode.yy \
      --redefine=conf/mariadb/versioning.yy \
      --redefine=conf/mariadb/sequences.yy \
      --redefine=conf/mariadb/modules/locks-10.4-extra.yy \
      --reporters=CrashRecovery1 \
      --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
      --mysqld=--loose-idle_write_transaction_timeout=0 \
      --mysqld=--loose-idle_transaction_timeout=0 \
      --mysqld=--loose-idle_readonly_transaction_timeout=0 \
      --mysqld=--connect_timeout=60 \
      --mysqld=--interactive_timeout=28800 \
      --mysqld=--slave_net_timeout=60 \
      --mysqld=--net_read_timeout=30 \
      --mysqld=--net_write_timeout=60 \
      --mysqld=--loose-table_lock_wait_timeout=50 \
      --mysqld=--wait_timeout=28800 \
      --mysqld=--lock-wait-timeout=86400 \
      --mysqld=--innodb-lock-wait-timeout=50 \
      --no-mask \
      --queries=10000000 \
      --seed=random \
      --reporters=Backtrace \
      --reporters=ErrorLog \
      --reporters=Deadlock1 \
      --validators=None \
      --mysqld=--log_output=none \
      --mysqld=--log-bin \
      --mysqld=--log_bin_trust_function_creators=1 \
      --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
      --engine=InnoDB \
      --restart_timeout=240 \
      --mysqld=--plugin-load-add=file_key_management.so \
      --mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
      --duration=100 \
      --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=600 \
      --mysqld=--innodb_stats_persistent=on \
      --mysqld=--innodb_adaptive_hash_index=off \
      --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
      --mysqld=--loose-max-statement-time=30 \
      --threads=2 \
      --mysqld=--innodb-use-native-aio=0 \
      --rr=Extended \
      --rr_options=--wait \
      --mysqld=--innodb_page_size=8K \
      --mysqld=--innodb-buffer-pool-size=256M \
      --duration=300 \
      --no_mask \
      --workdir=<local settings> \
      --vardir=<local settings> \
      --mtr-build-thread=<local settings> \
      --basedir1=<local settings> \
      --script_debug=_nix_
       
      Error pattern
      [ 'TBR-1081', 'INFO: Reporter \'CrashRecovery1\': Attempting database recovery using the server.+ERROR: OPTIMIZE TABLE .{1,500} harvested 2013: Lost connection to MySQL server during query.+\[Note\] InnoDB: Starting crash recovery from checkpoint LSN.+\[Note\] .{1,200}mysqld: ready for connections.+mysqld: .{1,200}sux_lock.h:.{1,10}: void sux_lock<srw>::s_lock\(\) \[with srw = ssux_lock_low\]: Assertion \`\!have_s\(\)\' failed..+RESULT: The RQG run ended with status STATUS_RECOVERY_FAILURE' ],
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              marko Marko Mäkelä
              Reporter:
              mleich Matthias Leich
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: