Reported latching order violation in ibuf_remove_free_page()

RQG test with server option --mysqld=--loose-innodb-sync-debug

[rr 3607879 378110]InnoDB: Failing assertion: latches->empty() || level == SYNC_LEVEL_VARYING || level == SYNC_NO_ORDER_CHECK || latches->back().get_level() == SYNC_NO_ORDER_CHECK || latches->back().m_latch->get_level() == SYNC_LEVEL_VARYING || latches->back().get_level() >= level

(rr) bt

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50

#1  0x00007f7cfe43f859 in __GI_abort () at abort.c:79

#2  0x000055e5188ab349 in ut_dbg_assertion_failed (

    expr=0x55e519bbd280 "latches->empty() || level == SYNC_LEVEL_VARYING || level == SYNC_NO_ORDER_CHECK || latches->back().get_level() == SYNC_NO_ORDER_CHECK || latches->back().m_latch->get_level() == SYNC_LEVEL_VARYING || l"..., 

    file=0x55e519bbd1c0 "/Server/bb-10.5-MDEV-24589/storage/innobase/sync/sync0debug.cc", line=219) at /Server/bb-10.5-MDEV-24589/storage/innobase/ut/ut0dbg.cc:60

#3  0x000055e518807653 in LatchDebug::lock_validate (this=0x60d000000040, latch=0x7f7cddd09320, level=SYNC_IBUF_PESS_INSERT_MUTEX) at /Server/bb-10.5-MDEV-24589/storage/innobase/sync/sync0debug.cc:219

#4  0x000055e518804371 in sync_check_lock_validate (latch=0x7f7cddd09320) at /Server/bb-10.5-MDEV-24589/storage/innobase/sync/sync0debug.cc:1057

#5  0x000055e5183e3cbe in MutexDebug<TTASEventMutex<GenericPolicy> >::enter (this=0x55e51b7ca030 <ibuf_pessimistic_insert_mutex+16>, mutex=..., filename=0x55e519a24680 "/Server/bb-10.5-MDEV-24589/storage/innobase/ibuf/ibuf0ibuf.cc", line=1918)

    at /Server/bb-10.5-MDEV-24589/storage/innobase/include/sync0policy.h:125

#6  0x000055e5183db874 in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x55e51b7ca020 <ibuf_pessimistic_insert_mutex>, n_spins=30, n_delay=4, name=0x55e519a24680 "/Server/bb-10.5-MDEV-24589/storage/innobase/ibuf/ibuf0ibuf.cc", 

    line=1918) at /Server/bb-10.5-MDEV-24589/storage/innobase/include/ib0mutex.h:588

#7  0x000055e5184dc067 in ibuf_remove_free_page () at /Server/bb-10.5-MDEV-24589/storage/innobase/ibuf/ibuf0ibuf.cc:1918

#8  0x000055e5184dc819 in ibuf_free_excess_pages () at /Server/bb-10.5-MDEV-24589/storage/innobase/ibuf/ibuf0ibuf.cc:2019

#9  0x000055e5186b7e15 in row_ins_sec_index_entry (index=0x617000037a08, entry=0x61b00033b988, thr=0x6210027f50d0, check_foreign=true) at /Server/bb-10.5-MDEV-24589/storage/innobase/row/row0ins.cc:3296

#10 0x000055e5186b804d in row_ins_index_entry (index=0x617000037a08, entry=0x61b00033b988, thr=0x6210027f50d0) at /Server/bb-10.5-MDEV-24589/storage/innobase/row/row0ins.cc:3335

#11 0x000055e5186b907b in row_ins_index_entry_step (node=0x6230001934f0, thr=0x6210027f50d0) at /Server/bb-10.5-MDEV-24589/storage/innobase/row/row0ins.cc:3502

#12 0x000055e5186b9a38 in row_ins (node=0x6230001934f0, thr=0x6210027f50d0) at /Server/bb-10.5-MDEV-24589/storage/innobase/row/row0ins.cc:3661

#13 0x000055e5186bab66 in row_ins_step (thr=0x6210027f50d0) at /Server/bb-10.5-MDEV-24589/storage/innobase/row/row0ins.cc:3807

#14 0x000055e5186fdbf3 in row_insert_for_mysql (mysql_rec=0x626000129138 "\347\377\376", prebuilt=0x623000192988, ins_mode=ROW_INS_NORMAL) at /Server/bb-10.5-MDEV-24589/storage/innobase/row/row0mysql.cc:1418

#15 0x000055e51838794c in ha_innobase::write_row (this=0x61d0007d28b8, record=0x626000129138 "\347\377\376") at /Server/bb-10.5-MDEV-24589/storage/innobase/handler/ha_innodb.cc:7673

#16 0x000055e517a8eb90 in handler::ha_write_row (this=0x61d0007d28b8, buf=0x626000129138 "\347\377\376") at /Server/bb-10.5-MDEV-24589/sql/handler.cc:7153

#17 0x000055e51724f169 in write_record (thd=0x62b000149218, table=0x61900033f998, info=0x7f7cddd0aff0, sink=0x0) at /Server/bb-10.5-MDEV-24589/sql/sql_insert.cc:2106

#18 0x000055e517247b45 in mysql_insert (thd=0x62b000149218, table_list=0x62b000118588, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0)

    at /Server/bb-10.5-MDEV-24589/sql/sql_insert.cc:1099

#19 0x000055e517301ed0 in mysql_execute_command (thd=0x62b000149218) at /Server/bb-10.5-MDEV-24589/sql/sql_parse.cc:4622

#20 0x000055e517318b86 in mysql_parse (thd=0x62b000149218, 

    rawbuf=0x62b000118238 "INSERT INTO `table100_innodb_int_autoinc` ( `col_set_ucs2`, `col_char_255_utf8_key`, `col_varchar_255_ucs2_key` ) VALUES ( REPEAT( _ASCII 0x1DAF, 15 ), REPEAT( _LATIN1 0x30E, 172 ), REPEAT( _UCS2 0xC,"..., length=245, 

    parser_state=0x7f7cddd0bcc0, is_com_multi=false, is_next_command=false) at /Server/bb-10.5-MDEV-24589/sql/sql_parse.cc:8093

#21 0x000055e5172f1035 in dispatch_command (command=COM_QUERY, thd=0x62b000149218, 

    packet=0x629000c30219 "INSERT INTO `table100_innodb_int_autoinc` ( `col_set_ucs2`, `col_char_255_utf8_key`, `col_varchar_255_ucs2_key` ) VALUES ( REPEAT( _ASCII 0x1DAF, 15 ), REPEAT( _LATIN1 0x30E, 172 ), REPEAT( _UCS2 0xC,"..., 

    packet_length=246, is_com_multi=false, is_next_command=false) at /Server/bb-10.5-MDEV-24589/sql/sql_parse.cc:1889

#22 0x000055e5172ee0c4 in do_command (thd=0x62b000149218) at /Server/bb-10.5-MDEV-24589/sql/sql_parse.cc:1370

#23 0x000055e5176cd6df in do_handle_one_connection (connect=0x6080000030b8, put_in_cache=true) at /Server/bb-10.5-MDEV-24589/sql/sql_connect.cc:1410

#24 0x000055e5176cd048 in handle_one_connection (arg=0x6080000030b8) at /Server/bb-10.5-MDEV-24589/sql/sql_connect.cc:1312

#25 0x00007f7cfe968609 in start_thread (arg=<optimized out>) at pthread_create.c:477

#26 0x00007f7cfe53c293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

(rr)

Query (0x62b000118238): INSERT INTO `table100_innodb_int_autoinc` ( `col_set_ucs2`, `col_char_255_utf8_key`, `col_varchar_255_ucs2_key` ) VALUES ( REPEAT( _ASCII 0x1DAF, 15 ), REPEAT( _LATIN1 0x30E, 172 ), REPEAT( _UCS2 0xC, 137 ) )

Status: KILL_TIMEOUT

sdp:/home/mleich/RQG_O/storage/1616623399/TBR-966/dev/shm/vardir/1616623399/6/1/rr

RQG

------

git clone https://github.com/mleich1/rqg --branch experimental RQG

perl rqg.pl \

--grammar=conf/engines/many_indexes.yy \

--gendata=conf/engines/many_indexes.zz \

--reporters=Mariabackup_linux \

--mysqld=--innodb_use_native_aio=1 \

--mysqld=--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=300 \

--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \

--mysqld=--loose-innodb-sync-debug \

--mysqld=--innodb_stats_persistent=off \

--mysqld=--innodb_adaptive_hash_index=off \

--mysqld=--loose-max-statement-time=30 \

--threads=2 \

--mysqld=--innodb_file_per_table=0 \

--rr=Extended \

--mysqld=--innodb_page_size=4K \

--mysqld=--innodb-buffer-pool-size=5M \

--duration=300 \

--no_mask \

--workdir=<local settings> \

--vardir=<local settings> \

--mtr-build-thread=<local settings> \

--basedir1=<local settings> \

--script_debug=_nix_