Potential hang in purge when virtual indexed columns exist

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' ],