Preliminary results of RQG testing on origin/bb-10.6-MDEV-29440 1c730da666ec50b131ca96a916a024c216632c28 2022-09-06T12:44:58+03:00
|
|
Per server error log
|
[rr 2537046 143119]mysqld: /data/Server/bb-10.6-MDEV-29440/storage/innobase/include/trx0trx.h:1027: void trx_t::assert_freed() const: Assertion `!lock.wait_thr' failed.
|
[rr 2537046 143139]220906 14:02:46 [rr 2537046 143142][ERROR] mysqld got signal 6 ;
|
....
|
[rr 2537046 164312]mysqld: /data/Server/bb-10.6-MDEV-29440/storage/innobase/lock/lock0lock.cc:5737: static dberr_t lock_sys_t::cancel(trx_t*, ib_lock_t*) [with bool check_victim = false]: Assertion `trx->state == TRX_STATE_ACTIVE' failed. <== This might be caused by the reaction of the system to the assertion above.
|
Both asserts were observed the first time when testing bb-10.6-MDEV-15250 March 2022.
|
But they did never show up since than.
|
|
pluto:/data/results/1662464247/TBR-1442-TBR-1443$ _RR_TRACE_DIR=./1/rr/ rr replay
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x000027ba0dd3a859 in __GI_abort () at abort.c:79
|
#2 0x000027ba0dd3a729 in __assert_fail_base (fmt=0x27ba0ded0588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55f6d9266a20 "!lock.wait_thr",
|
file=0x55f6d9266480 "/data/Server/bb-10.6-MDEV-29440/storage/innobase/include/trx0trx.h", line=1027, function=<optimized out>) at assert.c:92
|
#3 0x000027ba0dd4bf36 in __GI___assert_fail (assertion=0x55f6d9266a20 "!lock.wait_thr", file=0x55f6d9266480 "/data/Server/bb-10.6-MDEV-29440/storage/innobase/include/trx0trx.h", line=1027,
|
function=0x55f6d92667e0 "void trx_t::assert_freed() const") at assert.c:101
|
#4 0x000055f6d80dfd1c in trx_t::assert_freed (this=0x780c056f7e40) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/include/trx0trx.h:1027
|
#5 0x000055f6d80d87c1 in trx_t::commit_cleanup (this=0x780c056f7e40) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/trx/trx0trx.cc:1395
|
#6 0x000055f6d80db1e2 in trx_t::commit (this=0x780c056f7e40) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/trx/trx0trx.cc:1483
|
#7 0x000055f6d80bc04f in trx_t::rollback_finish (this=0x780c056f7e40) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/trx/trx0roll.cc:66
|
#8 0x000055f6d80bcdb6 in trx_t::rollback_low (this=0x780c056f7e40, savept=0x0) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/trx/trx0roll.cc:133
|
#9 0x000055f6d80b718f in trx_t::rollback (this=0x780c056f7e40, savept=0x0) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/trx/trx0roll.cc:176
|
#10 0x000055f6d7f946b3 in row_mysql_handle_errors (new_err=0x2d105d0e33f0, trx=0x780c056f7e40, thr=0x6210004030b0, savept=0x2d105d0e3400) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/row/row0mysql.cc:696
|
#11 0x000055f6d7f98927 in row_insert_for_mysql (mysql_rec=0x61a00032eeb8 "\377", prebuilt=0x621000402588, ins_mode=ROW_INS_NORMAL) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/row/row0mysql.cc:1319
|
#12 0x000055f6d7c0ce83 in ha_innobase::write_row (this=0x61d0005848b8, record=0x61a00032eeb8 "\377") at /data/Server/bb-10.6-MDEV-29440/storage/innobase/handler/ha_innodb.cc:7935
|
#13 0x000055f6d732b678 in handler::ha_write_row (this=0x61d0005848b8, buf=0x61a00032eeb8 "\377") at /data/Server/bb-10.6-MDEV-29440/sql/handler.cc:7575
|
#14 0x000055f6d6a717ca in write_record (thd=0x62b00023e218, table=0x61900034e498, info=0x2d105d0e3de0, sink=0x0) at /data/Server/bb-10.6-MDEV-29440/sql/sql_insert.cc:2156
|
#15 0x000055f6d6a69e9f in mysql_insert (thd=0x62b00023e218, table_list=0x62b0002454c8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0)
|
at /data/Server/bb-10.6-MDEV-29440/sql/sql_insert.cc:1128
|
#16 0x000055f6d6b28221 in mysql_execute_command (thd=0x62b00023e218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-MDEV-29440/sql/sql_parse.cc:4565
|
#17 0x000055f6d6b3f4ef in mysql_parse (thd=0x62b00023e218,
|
rawbuf=0x62b000245238 "INSERT INTO t2 (col1,col2, col_int, col_string, col_text) VALUES ( NULL, NULL, NULL, REPEAT(SUBSTR(CAST( NULL AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( NULL AS CHAR),1,1), @fill_amount) ) /* E_R Thread2"..., length=221, parser_state=0x2d105d0e4a20) at /data/Server/bb-10.6-MDEV-29440/sql/sql_parse.cc:8030
|
#18 0x000055f6d6b17871 in dispatch_command (command=COM_QUERY, thd=0x62b00023e218,
|
packet=0x629000e9c219 " INSERT INTO t2 (col1,col2, col_int, col_string, col_text) VALUES ( NULL, NULL, NULL, REPEAT(SUBSTR(CAST( NULL AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( NULL AS CHAR),1,1), @fill_amount) ) /* E_R Thread"..., packet_length=223, blocking=true) at /data/Server/bb-10.6-MDEV-29440/sql/sql_parse.cc:1896
|
#19 0x000055f6d6b14c9a in do_command (thd=0x62b00023e218, blocking=true) at /data/Server/bb-10.6-MDEV-29440/sql/sql_parse.cc:1409
|
#20 0x000055f6d6f19623 in do_handle_one_connection (connect=0x608000003bb8, put_in_cache=true) at /data/Server/bb-10.6-MDEV-29440/sql/sql_connect.cc:1418
|
#21 0x000055f6d6f18eaf in handle_one_connection (arg=0x608000003bb8) at /data/Server/bb-10.6-MDEV-29440/sql/sql_connect.cc:1312
|
#22 0x00007f34e094a609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#23 0x000027ba0de37293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
|
# git clone https://github.com/mleich1/rqg --branch experimental RQG
|
#
|
# GIT_SHOW: HEAD -> experimental, origin/experimental 870d6d8aa40c27a3b53e445e8fc86aae51cba19c 2022-08-30T20:57:51+02:00
|
# rqg.pl : Version 4.0.6 (2022-05)
|
#
|
# $RQG_HOME/rqg.pl \
|
# --grammar=conf/mariadb/table_stress_innodb.yy \
|
# --gendata=conf/mariadb/table_stress.zz \
|
# --gendata_sql=conf/mariadb/table_stress.sql \
|
# --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_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 \
|
# --mysqld=--plugin-load-add=provider_lzo.so \
|
# --mysqld=--plugin-load-add=provider_bzip2.so \
|
# --mysqld=--plugin-load-add=provider_lzma.so \
|
# --mysqld=--plugin-load-add=provider_snappy.so \
|
# --mysqld=--plugin-load-add=provider_lz4.so \
|
# --duration=300 \
|
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
|
# --mysqld=--innodb_file_per_table=1 \
|
# --mysqld=--loose-innodb_read_only_compressed=OFF \
|
# --mysqld=--loose-innodb-sync-debug \
|
# --mysqld=--innodb_stats_persistent=off \
|
# --mysqld=--innodb_adaptive_hash_index=off \
|
# --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
|
# --mysqld=--loose-max-statement-time=30 \
|
# --threads=33 \
|
# --mysqld=--innodb-use-native-aio=0 \
|
# --mysqld=--loose-gdb \
|
# --mysqld=--loose-debug-gdb \
|
# --rr=Extended \
|
# --rr_options=--chaos --wait \
|
# --mysqld=--loose_innodb_change_buffering=deletes \
|
# --mysqld=--innodb_rollback_on_timeout=ON \ <== Could that play some important role?
|
# --mysqld=--innodb_page_size=4K \
|
# --mysqld=--innodb-buffer-pool-size=5M \
|
# <local settings>
|
A slightly different test case (I am trying to reproduce
MDEV-29438without hitting this bug):--source include/have_innodb.inc
--source include/not_embedded.inc
--source include/have_debug.inc
--source include/have_debug_sync.inc
ENGINE=InnoDB;
--send
--source include/kill_mysqld.inc
disconnect ddl;
--source include/start_mysqld.inc
10.6 40aa94df356cfa000fc43c92ff0061212d1b161d
2022-09-01 14:55:27 0 [ERROR] InnoDB: Table `test`.`t2` contains unrecognizable instant ALTER metadata
mariadbd: /mariadb/10.6/storage/innobase/dict/dict0load.cc:2464: dict_table_t* dict_load_table_one(const st_::span<const char>&, dict_err_ignore_t, dict_names_t&): Assertion `!table || (ignore_err & ~DICT_ERR_IGNORE_FK_NOKEY) || !table->is_readable() || !table->corrupted' failed.