[MDEV-24434] Assertion `trx->in_rw_trx_list || trx->state == TRX_STATE_NOT_STARTED || trx->state == TRX_STATE_ACTIVE' failed in trx_sys_any_active_transactions Created: 2020-12-18  Updated: 2021-04-12  Resolved: 2021-04-12

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2
Fix Version/s: 10.2.38

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: rr-profile


 Description   

10.2 25d6f634b

 
mysqld: /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0sys.cc:1002: ulint trx_sys_any_active_transactions(): Assertion `trx->in_rw_trx_list || trx->state == TRX_STATE_NOT_STARTED || trx->state == TRX_STATE_ACTIVE' failed.
 
201218  1:37:39 [ERROR] mysqld got signal 6 ;
 
 
 
#1  0x00007fb9116388b1 in __GI_abort () at abort.c:79
 
#2  0x00007fb91162842a in __assert_fail_base (fmt=0x7fb9117afa38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", 
    assertion=assertion@entry=0x5653337e63c0 "trx->in_rw_trx_list || trx->state == TRX_STATE_NOT_STARTED || trx->state == TRX_STATE_ACTIVE", 
    file=file@entry=0x5653337e5d58 "/home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0sys.cc", line=line@entry=1002, 
    function=function@entry=0x5653337e7080 <trx_sys_any_active_transactions()::__PRETTY_FUNCTION__> "ulint trx_sys_any_active_transactions()") at assert.c:92
 
#3  0x00007fb9116284a2 in __GI___assert_fail (assertion=0x5653337e63c0 "trx->in_rw_trx_list || trx->state == TRX_STATE_NOT_STARTED || trx->state == TRX_STATE_ACTIVE", 
    file=0x5653337e5d58 "/home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0sys.cc", line=1002, function=0x5653337e7080 <trx_sys_any_active_transactions()::__PRETTY_FUNCTION__> "ulint trx_sys_any_active_transactions()")
 
    at assert.c:101
 
#4  0x00005653331b8d0b in trx_sys_any_active_transactions () at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0sys.cc:1002
 
#5  0x0000565333107eda in row_drop_tables_for_mysql_in_background () at /home/mariadb/MDEV-24434/10.2/storage/innobase/row/row0mysql.cc:2589
 
#6  0x000056533316d8c7 in srv_master_do_active_tasks () at /home/mariadb/MDEV-24434/10.2/storage/innobase/srv/srv0srv.cc:2216
 
#7  0x000056533316e460 in srv_master_thread (arg=0x0) at /home/mariadb/MDEV-24434/10.2/storage/innobase/srv/srv0srv.cc:2468
 
#8  0x00007fb91232f6db in start_thread (arg=0x7fb8bfcff700) at pthread_create.c:463
 
#9  0x00007fb911719a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

rr profile is available.

I couldn't reproduce it on 10.3+ right away, but it's not a guarantee that the problem doesn't exist there.

For the record, I used this test run to reproduce the failure (works with and without rr, but with rr it takes much longer):

MariaDB/randgen branch mdev24434

 
perl ./runall-trials.pl --grammar=conf/partitioning/partitions.yy --gendata-advanced --skip-gendata --duration=350 --seed=1608184357 --reporters=Backtrace,ErrorLog,Deadlock --partitions  --engine=InnoDB,MyISAM,Aria --filter=conf/mariadb/10.4-combo-filter.ff --redefine=conf/mariadb/bulk_insert.yy --redefine=conf/mariadb/alter_table.yy  --redefine=conf/mariadb/modules/admin.yy --redefine=conf/mariadb/modules/alter_table_columns.yy --redefine=conf/mariadb/modules/alter_table_indexes.yy --redefine=conf/mariadb/modules/foreign_keys.yy  --mysqld=--server-id=111 --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=10 --mysqld=--innodb-lock-wait-timeout=5 --threads=3 --redefine=conf/mariadb/modules/dynamic_variables.yy --validators=TransformerNoComparator --transformers=ExecuteAsCTE,ExecuteAsExecuteImmediate,ExecuteAsDeleteReturning,ExecuteAsInsertSelect,ExecuteAsUnion,ExecuteAsUpdateDelete,ExecuteAsPreparedTwice --mysqld=--log-bin --mysqld=--log_bin_trust_function_creators=1 --basedir1=`pwd`/../10.2 --vardir1=/dev/shm/var_mdev24434 --rr --trials=50



 Comments   
Comment by Marko Mäkelä [ 2021-04-12 ]

The transaction in question was in PREPARE state and is in the process of being committed:

10.2 25d6f634b89c4b1ad8ae721921b5ccf595073270

 
#6  0x00005653331ccc02 in trx_undo_seg_free (undo=0x7fb86c17d6a0, noredo=false)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0undo.cc:1088
 
#7  0x00005653331cec07 in trx_undo_commit_cleanup (undo=0x7fb86c17d6a0, 
    is_temp=false)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0undo.cc:1789
 
#8  0x00005653331beeba in trx_commit_in_memory (trx=0x7fb9105fc228, 
    mtr=0x7fb8d40f1c20, serialised=true)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0trx.cc:1773
 
#9  0x00005653331bf90e in trx_commit_low (trx=0x7fb9105fc228, 
    mtr=0x7fb8d40f1c20)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0trx.cc:1957
 
#10 0x00005653331bf9c6 in trx_commit (trx=0x7fb9105fc228)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0trx.cc:1981
 
#11 0x00005653331c0273 in trx_commit_for_mysql (trx=0x7fb9105fc228)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0trx.cc:2190
 
#12 0x0000565332fbf1f4 in innobase_commit_low (trx=0x7fb9105fc228)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/handler/ha_innodb.cc:4432
 
#13 0x0000565332fbf537 in innobase_commit_ordered_2 (trx=0x7fb9105fc228, 
    thd=0x7fb86c000d50)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/handler/ha_innodb.cc:4556
 
#14 0x0000565332fbf708 in innobase_commit_ordered (hton=0x565335bfa2c0, 
    thd=0x7fb86c000d50, all=true)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/handler/ha_innodb.cc:4616
 
#15 0x0000565332ed3f7e in TC_LOG::run_commit_ordered (
 
    this=0x565334139260 <mysql_bin_log>, thd=0x7fb86c000d50, all=true)
 
    at /home/mariadb/MDEV-24434/10.2/sql/log.cc:8842
 
#16 0x0000565332ed1ee2 in MYSQL_BIN_LOG::trx_group_commit_leader (
 
    this=0x565334139260 <mysql_bin_log>, leader=0x7fb8d40f23d0)
 
    at /home/mariadb/MDEV-24434/10.2/sql/log.cc:8069
 
#17 0x0000565332ed0ea5 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (
 
    this=0x565334139260 <mysql_bin_log>, entry=0x7fb8d40f23d0)
 
    at /home/mariadb/MDEV-24434/10.2/sql/log.cc:7645
 
#18 0x0000565332ed0511 in MYSQL_BIN_LOG::write_transaction_to_binlog (
 
    this=0x565334139260 <mysql_bin_log>, thd=0x7fb86c000d50, 
    cache_mngr=0x7fb86c9e5080, end_ev=0x7fb8d40f2570, all=true, 
    using_stmt_cache=true, using_trx_cache=true)
 
    at /home/mariadb/MDEV-24434/10.2/sql/log.cc:7319
 
#19 0x0000565332ec1afe in binlog_flush_cache (thd=0x7fb86c000d50, 
    cache_mngr=0x7fb86c9e5080, end_ev=0x7fb8d40f2570, all=true, 
    using_stmt=true, using_trx=true)
 
    at /home/mariadb/MDEV-24434/10.2/sql/log.cc:1745
 
#20 0x0000565332ec203f in binlog_commit_flush_xid_caches (thd=0x7fb86c000d50, 
    cache_mngr=0x7fb86c9e5080, all=true, xid=8153)
 
    at /home/mariadb/MDEV-24434/10.2/sql/log.cc:1853
 
#21 0x0000565332ed6011 in MYSQL_BIN_LOG::log_and_order (
 
    this=0x565334139260 <mysql_bin_log>, thd=0x7fb86c000d50, xid=8153, 
    all=true, need_prepare_ordered=false, need_commit_ordered=true)
 
    at /home/mariadb/MDEV-24434/10.2/sql/log.cc:9625
 
#22 0x0000565332dc6969 in ha_commit_trans (thd=0x7fb86c000d50, all=true)
 
    at /home/mariadb/MDEV-24434/10.2/sql/handler.cc:1496
 
#23 0x0000565332caef3b in trans_commit_implicit (thd=0x7fb86c000d50)
 
    at /home/mariadb/MDEV-24434/10.2/sql/transaction.cc:368
 
#24 0x0000565332b484a0 in mysql_execute_command (thd=0x7fb86c000d50)
 
    at /home/mariadb/MDEV-24434/10.2/sql/sql_parse.cc:3407
 
#25 0x0000565332b55f13 in mysql_parse (thd=0x7fb86c000d50, 
    rawbuf=0x7fb86c013548 "DROP /* QNO 3172 CON_ID 15 */ TABLE transforms.insert_select_45800", length=66, parser_state=0x7fb8d40f3640, is_com_multi=false, 
    is_next_command=false)
 
    at /home/mariadb/MDEV-24434/10.2/sql/sql_parse.cc:7762

The assertion is failing, because the transaction had been removed from the rw_trx_list and its state is TRX_STATE_COMMITTED_IN_MEMORY:

#0  0x00005653331be5bb in trx_erase_lists (trx=0x7fb9105fc228, serialised=true)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0trx.cc:1657
 
#1  0x00005653331beb00 in trx_commit_in_memory (trx=0x7fb9105fc228, 
    mtr=0x7fb8d40f1c20, serialised=true)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0trx.cc:1733
 
#2  0x00005653331bf90e in trx_commit_low (trx=0x7fb9105fc228, 
    mtr=0x7fb8d40f1c20)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0trx.cc:1957
 
#3  0x00005653331bf9c6 in trx_commit (trx=0x7fb9105fc228)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0trx.cc:1981
 
#4  0x00005653331c0273 in trx_commit_for_mysql (trx=0x7fb9105fc228)
 
    at /home/mariadb/MDEV-24434/10.2/storage/innobase/trx/trx0trx.cc:2190

I think that the following should be an acceptable fix:

diff --git a/storage/innobase/trx/trx0sys.cc b/storage/innobase/trx/trx0sys.cc
 
index 8d00bd824a2..0f18850fb2e 100644
 
--- a/storage/innobase/trx/trx0sys.cc
 
+++ b/storage/innobase/trx/trx0sys.cc
 
@@ -997,11 +997,6 @@ trx_sys_any_active_transactions(void)
 
 		/* This may count some ACTIVE transactions twice,
 
 		both in rw_trx_list and mysql_trx_list. */
 
 		total_trx += trx->state == TRX_STATE_ACTIVE;
 
-		/* Any PREPARED or COMMITTED transactions must be
 
-		in rw_trx_list, so it suffices to count them there. */
 
-		ut_ad(trx->in_rw_trx_list
 
-		      || trx->state == TRX_STATE_NOT_STARTED
 
-		      || trx->state == TRX_STATE_ACTIVE);
 
 		trx_mutex_exit(trx);
 
 	}

In 10.3, the list was replaced by trx_sys.rw_trx_hash and this code is rather different. Like the surviving comment says, the count returned by trx_sys_any_active_transactions() is not accurate. It is only being tested for 0, so the duplicate counts should be harmless.

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