[MDEV-29576] InnoDB: Failing assertion: thr_get_trx(thr)->error_state == DB_SUCCESS Created: 2022-09-20  Updated: 2023-07-11  Resolved: 2023-07-11

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.6.10, 10.7.6
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Matthias Leich Assignee: Vladislav Lesin
Resolution: Cannot Reproduce Votes: 0
Labels: need_rr


 Description    

origin/bb-10.6-MDEV-27927-RR-anomaly fd6f4cf9474efdc1c017218967757e6f852fa208 2022-09-12T18:49:53+03:00
 
origin/bb-10.6-MDEV-22718 62de4addd247fceced29674b4a29dfec72b4340b 2022-09-19T15:30:09+03:00
 
origin/10.7 f3785f099c2f0f251f39632928e822328abe9a02 2022-09-13T08:48:40+03:00
 
 
 
# 2022-09-16T14:05:35 [619751] | [rr 622261 159070]2022-09-16 14:01:34 0x4bb11df40700[rr 622261 159073]  InnoDB: Assertion failure in file /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/que/que0que.cc line 677
 
# 2022-09-16T14:05:35 [619751] | [rr 622261 159075]InnoDB: Failing assertion: thr_get_trx(thr)->error_state == DB_SUCCESS
 
...
 
Query (0x62b0001a4238): UPDATE `table100_innodb_int_autoinc` SET `col_int` = 0 WHERE `col_int` BETWEEN 1 and 9 LIMIT 2
 
[rr 622261 186621]Status: KILL_TIMEOUT
 
 
 
(rr) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x00004d7e18368859 in __GI_abort () at abort.c:79
 
#2  0x00005617914dc8d7 in ut_dbg_assertion_failed (expr=0x5617925624e0 "thr_get_trx(thr)->error_state == DB_SUCCESS", file=0x561792561720 "/data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/que/que0que.cc", line=677)
 
    at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/ut/ut0dbg.cc:60
 
#3  0x00005617912b0235 in que_thr_step (thr=0x616006f1a018) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/que/que0que.cc:677
 
#4  0x00005617912b0430 in que_run_threads_low (thr=0x616006f1a018) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/que/que0que.cc:709
 
#5  0x00005617912b05d2 in que_run_threads (thr=0x616006f1a018) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/que/que0que.cc:729
 
#6  0x000056179149b102 in trx_t::rollback_low (this=0x2c9272ee1940, savept=0x0) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/trx/trx0roll.cc:124
 
#7  0x0000561791495593 in trx_t::rollback (this=0x2c9272ee1940, savept=0x0) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/trx/trx0roll.cc:176
 
#8  0x0000561791372f1b in row_mysql_handle_errors (new_err=0x4bb11df3c430, trx=0x2c9272ee1940, thr=0x620000271848, savept=0x0) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/row/row0mysql.cc:696
 
#9  0x00005617913f525f in row_search_mvcc (buf=0x61900055e6e0 <incomplete sequence \371>, mode=PAGE_CUR_G, prebuilt=0x620000271108, match_mode=0, direction=1)
 
    at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/row/row0sel.cc:5845
 
#10 0x0000561790ff3c2d in ha_innobase::general_fetch (this=0x61d0008840b8, buf=0x61900055e6e0 <incomplete sequence \371>, direction=1, match_mode=0)
 
    at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/handler/ha_innodb.cc:9349
 
#11 0x0000561790ff46a3 in ha_innobase::rnd_next (this=0x61d0008840b8, buf=0x61900055e6e0 <incomplete sequence \371>) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/handler/ha_innodb.cc:9553
 
#12 0x00005617906f00e4 in handler::ha_rnd_next (this=0x61d0008840b8, buf=0x61900055e6e0 <incomplete sequence \371>) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/sql/handler.cc:3417
 
#13 0x0000561790afc913 in rr_sequential (info=0x4bb11df3d9c0) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/sql/records.cc:519
 
#14 0x000056178fd6fd1a in READ_RECORD::read_record (this=0x4bb11df3d9c0) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/sql/records.h:81
 
#15 0x00005617901ea811 in mysql_update (thd=0x62b00019d218, table_list=0x62b0001a44a8, fields=..., values=..., conds=0x62b0001a5038, order_num=0, order=0x0, limit=1, ignore=false, found_return=0x4bb11df3e1f0, 
    updated_return=0x4bb11df3e210) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/sql/sql_update.cc:1006
 
#16 0x000056178ff08ee5 in mysql_execute_command (thd=0x62b00019d218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/sql/sql_parse.cc:4408
 
#17 0x000056178ff21329 in mysql_parse (thd=0x62b00019d218, rawbuf=0x62b0001a4238 "UPDATE `table100_innodb_int_autoinc` SET `col_int` = 0 WHERE `col_int` BETWEEN 1 and 9 LIMIT 2 /* E_R Thread12 QNO 81 CON_ID 26 */", length=130, 
    parser_state=0x4bb11df3ea20) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/sql/sql_parse.cc:8030
 
#18 0x000056178fef96ab in dispatch_command (command=COM_QUERY, thd=0x62b00019d218, 
    packet=0x629000d1b219 "UPDATE `table100_innodb_int_autoinc` SET `col_int` = 0 WHERE `col_int` BETWEEN 1 and 9 LIMIT 2 /* E_R Thread12 QNO 81 CON_ID 26 */ ", packet_length=131, blocking=true)
 
    at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/sql/sql_parse.cc:1896
 
#19 0x000056178fef6ad4 in do_command (thd=0x62b00019d218, blocking=true) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/sql/sql_parse.cc:1409
 
#20 0x00005617902fb45d in do_handle_one_connection (connect=0x6080000036b8, put_in_cache=true) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/sql/sql_connect.cc:1416
 
#21 0x00005617902fadba in handle_one_connection (arg=0x6080000036b8) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/sql/sql_connect.cc:1318
 
#22 0x00007fd23b9a3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#23 0x00004d7e18465293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
(rr)
 
 
 
sdp:/data/results/1663358263/TBR-1607$ _RR_TRACE_DIR="./dev/shm/rqg/1663358263/166/1/rr" rr replay --mark-stdio
 
 
 
RQG
 
===
 
# git clone https://github.com/mleich1/rqg --branch experimental RQG
 
#
 
# GIT_SHOW: HEAD -> experimental, origin/experimental 9c333aebe04973365c0b91b363957f00362f2605 2022-09-12T18:19:28+02:00
 
# rqg.pl  : Version 4.0.5 (2022-04)
 
#
 
# $RQG_HOME/rqg.pl \
 
# --grammar=conf/transactions/repeatable_read.yy \
 
# --gendata=conf/transactions/transactions.zz \
 
# --mysqld=--transaction-isolation=READ-COMMITTED \
 
# --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=0 \
 
# --mysqld=--loose-innodb_read_only_compressed=OFF \
 
# --mysqld=--loose-innodb-sync-debug \
 
# --mysqld=--innodb_stats_persistent=off \                             # not important
 
# --mysqld=--innodb_adaptive_hash_index=on \                     # not important
 
# --mysqld=--log-bin \
 
# --mysqld=--sync-binlog=1 \
 
# --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \   # not important
 
# --mysqld=--loose-max-statement-time=30 \
 
# --threads=33 \
 
# --mysqld=--innodb-use-native-aio=1 \
 
# --mysqld=--innodb_undo_tablespaces=3 \                               # not important
 
# --mysqld=--innodb_undo_log_truncate=ON \                         # not important
 
# --mysqld=--loose_innodb_change_buffering=all \
 
# --mysqld=--innodb_rollback_on_timeout=ON \                      # not important
 
# --mysqld=--innodb_page_size=4K \
 
# --mysqld=--innodb-buffer-pool-size=5M \
 
# --duration=300 \
 
# --no_mask \
 
# <local settings>
 
 
 
The options marked with "# not important" were present in the RQG run the rr
 
trace belongs to. But there other replays of the problem where these options
 
were not set.



 Comments   
Comment by Marko Mäkelä [ 2022-09-20 ]

The transaction state was changed by another thread:

0x000056179116488d in lock_wait_end (trx=0x2c9272ee1940)
 
    at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/lock/lock0lock.cc:1896
 
1896	    trx->error_state= DB_DEADLOCK;

At this point of time, the rollback in Thread 3 was waiting for a lock:

#13 0x000056179103869e in trx_t::mutex_lock (this=0x2c9272ee1940) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/include/trx0trx.h:608
 
#14 0x0000561791499c2c in trx_rollback_step (thr=0x616006f1a018) at /data/Server/bb-10.6-MDEV-27927-RR-anomaly/storage/innobase/trx/trx0roll.cc:913

In other words, the transaction was chosen as a deadlock victim even though a rollback was already in progress. The full rollback in row_mysql_handle_errors() was being triggered due to innodb_rollback_on_timeout=ON.

Comment by Vladislav Lesin [ 2023-07-11 ]

As we can't reproduce it on fresh 10.6, I am closing it. Please feel free to reopen if we are able to reproduce it.

Generated at Thu Feb 08 10:09:40 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.