[MDEV-11197] TrxInInnoDB::is_aborted(const trx_t*): Assertion `srv_read_only_mode || trx->in_depth > 0' failed Created: 2016-10-31  Updated: 2017-05-10  Resolved: 2017-05-10

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

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: None


 Description   

10.2 1ca8637ae35061

 
mysqld: /data/src/10.2/storage/innobase/include/trx0trx.h:1423: static bool TrxInInnoDB::is_aborted(const trx_t*): Assertion `srv_read_only_mode || trx->in_depth > 0' failed.
 
170321 19:54:53 [ERROR] mysqld got signal 6 ;


# 2017-03-21T19:55:03 [23375] #7  0x00007f1af3371312 in __GI___assert_fail (assertion=0x7f1af67ef450 "srv_read_only_mode || trx->in_depth > 0", file=0x7f1af67ef418 "/data/src/10.2/storage/innobase/include/trx0trx.h", line=1423, function=0x7f1af67fde60 <TrxInInnoDB::is_aborted(trx_t const*)::__PRETTY_FUNCTION__> "static bool TrxInInnoDB::is_aborted(const trx_t*)") at assert.c:101
 
# 2017-03-21T19:55:03 [23375] #8  0x00007f1af61e7259 in TrxInInnoDB::is_aborted (trx=0x7f1adf401168) at /data/src/10.2/storage/innobase/include/trx0trx.h:1423
 
# 2017-03-21T19:55:03 [23375] #9  0x00007f1af61cee0c in ha_innobase::general_fetch (this=0x7f1ac0ca6888, buf=0x7f1ac0c1e488 "\375\001", direction=1, match_mode=0) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:10304
 
# 2017-03-21T19:55:03 [23375] #10 0x00007f1af61cf4a0 in ha_innobase::rnd_next (this=0x7f1ac0ca6888, buf=0x7f1ac0c1e488 "\375\001") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:10532
 
# 2017-03-21T19:55:03 [23375] #11 0x00007f1af5ebe121 in handler::ha_rnd_next (this=0x7f1ac0ca6888, buf=0x7f1ac0c1e488 "\375\001") at /data/src/10.2/sql/handler.cc:2577
 
# 2017-03-21T19:55:03 [23375] #12 0x00007f1af60268bc in rr_sequential (info=0x7f1ac0c62188) at /data/src/10.2/sql/records.cc:484
 
# 2017-03-21T19:55:03 [23375] #13 0x00007f1af5cbd0be in sub_select (join=0x7f1ac0c60ff0, join_tab=0x7f1ac0c620c0, end_of_records=false) at /data/src/10.2/sql/sql_select.cc:18436
 
# 2017-03-21T19:55:03 [23375] #14 0x00007f1af5cbc5a3 in do_select (join=0x7f1ac0c60ff0, procedure=0x0) at /data/src/10.2/sql/sql_select.cc:17961
 
# 2017-03-21T19:55:03 [23375] #15 0x00007f1af5c975b7 in JOIN::exec_inner (this=0x7f1ac0c60ff0) at /data/src/10.2/sql/sql_select.cc:3463
 
# 2017-03-21T19:55:03 [23375] #16 0x00007f1af5c96abc in JOIN::exec (this=0x7f1ac0c60ff0) at /data/src/10.2/sql/sql_select.cc:3266
 
# 2017-03-21T19:55:03 [23375] #17 0x00007f1af5c97c2f in mysql_select (thd=0x7f1ac0c16070, tables=0x7f1ac0c608f8, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=553247836928, result=0x7f1ac0c60f48, unit=0x7f1ac0c19b50, select_lex=0x7f1ac0c1a280) at /data/src/10.2/sql/sql_select.cc:3658
 
# 2017-03-21T19:55:03 [23375] #18 0x00007f1af5c8c710 in handle_select (thd=0x7f1ac0c16070, lex=0x7f1ac0c19a88, result=0x7f1ac0c60f48, setup_tables_done_option=1073741824) at /data/src/10.2/sql/sql_select.cc:373
 
# 2017-03-21T19:55:03 [23375] #19 0x00007f1af5c51b98 in mysql_execute_command (thd=0x7f1ac0c16070) at /data/src/10.2/sql/sql_parse.cc:4498
 
# 2017-03-21T19:55:03 [23375] #20 0x00007f1af5c5c52c in mysql_parse (thd=0x7f1ac0c16070, rawbuf=0x7f1ac0c60088 "INSERT INTO tmp SELECT * FROM t2  /* QNO 31 CON_ID 12 */", length=56, parser_state=0x7f1af6d28e20, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7858
 
# 2017-03-21T19:55:03 [23375] #21 0x00007f1af5c4a5f2 in dispatch_command (command=COM_QUERY, thd=0x7f1ac0c16070, packet=0x7f1ac0c54071 " INSERT INTO tmp SELECT * FROM t2  /* QNO 31 CON_ID 12 */ ", packet_length=58, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1812
 
# 2017-03-21T19:55:03 [23375] #22 0x00007f1af5c48f62 in do_command (thd=0x7f1ac0c16070) at /data/src/10.2/sql/sql_parse.cc:1362
 
# 2017-03-21T19:55:03 [23375] #23 0x00007f1af5d91f3f in do_handle_one_connection (connect=0x7f1af2853870) at /data/src/10.2/sql/sql_connect.cc:1358
 
# 2017-03-21T19:55:03 [23375] #24 0x00007f1af5d91ccc in handle_one_connection (arg=0x7f1af2853870) at /data/src/10.2/sql/sql_connect.cc:1264
 
# 2017-03-21T19:55:03 [23375] #25 0x00007f1af5273064 in start_thread (arg=0x7f1af6d2a300) at pthread_create.c:309
 
# 2017-03-21T19:55:03 [23375] #26 0x00007f1af342b62d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Non-deterministic concurrent test

git clone https://github.com/elenst/rqg --branch mdev11197 rqg-mdev11197
 
cd rqg-mdev11197
 
perl ./runall-new.pl --skip-gendata --duration=300 --threads=2 --grammar=conf/mariadb/mdev11197.yy --basedir=<your 10.2 basedir> --vardir=<your vardir>
 
# or, if you want to run it on an already started server (e.g. under debugger), 
# assuming it's running on port 3306
 
perl ./gentest.pl --duration=300 --threads=2 --grammar=conf/mariadb/mdev11197.yy --dsn='dbi:mysql:host=127.0.0.1:port=3306:user=root:database=test'



 Comments   
Comment by Marko Mäkelä [ 2017-04-04 ]

It seems to me that there could be a problem when merging from MySQL 5.7. The function innobase_kill_connection() which is bound to handlerton::kill_connection does not exist in MariaDB, but instead we have a similar function innobase_kill_query() that is bound to handlerton::kill_query().

At the very least, comments that refer to innobase_kill_connection() should be revised to refer to innobase_kill_query(). I suspect some difference near lock_trx_handle_wait().

While I was investigating this bug, I came up with the following clean-up patch that might marginally improve performance:

diff --git a/storage/innobase/include/trx0trx.h b/storage/innobase/include/trx0trx.h
 
index d0a67a7ed28..2d4132237af 100644
 
--- a/storage/innobase/include/trx0trx.h
 
+++ b/storage/innobase/include/trx0trx.h
 
@@ -1473,12 +1473,8 @@ class TrxInInnoDB {
 
 
 		ut_ad(!is_async_rollback(trx));
 
 
-		++trx->in_depth;
 
-
 
-		/* If trx->in_depth is greater than 1 then
 
-		transaction is already in InnoDB. */
 
-		if (trx->in_depth > 1) {
 
-
 
+		if (trx->in_depth++) {
 
+			/* The transaction is already inside InnoDB. */
 
 			return;
 
 		}
 
 
@@ -1528,9 +1524,7 @@ class TrxInInnoDB {
 
 
 		ut_ad(trx->in_depth > 0);
 
 
-		--trx->in_depth;
 
-
 
-		if (trx->in_depth > 0) {
 
+		if (--trx->in_depth > 0) {
 
 
 			return;
 
 		}

Also, while I was looking at this, I noticed that my change to deprecate innodb_support_xa in MySQL 5.7.10 has not been merged.

Comment by Elena Stepanova [ 2017-05-06 ]

Happened again, 10.2 revision 8f05c848c5d856f53fa907ae202deac465a17656.

Comment by Jan Lindström (Inactive) [ 2017-05-08 ]

To me this looks like optimizer does not stop when InnoDB has already reported transaction abort instead it just continues the statement execution but InnoDB has already thrown transaction away.

Comment by Jan Lindström (Inactive) [ 2017-05-10 ]

Does not repeat with MySQL 5.7.18, repeats easily with current 10.2.

Comment by Jan Lindström (Inactive) [ 2017-05-10 ]

http://lists.askmonty.org/pipermail/commits/2017-May/011141.html

Could not yet construct repeatable test case from RQG test case log.

Comment by Marko Mäkelä [ 2017-05-10 ]

Please include my clean-up patch as well, and do not construct the TrxInInnoDB object before DBUG_ENTER.

For what it is worth, starting with MDEV-11236, InnoDB in MariaDB now tolerates (and ignores) a statement rollback from the SQL layer even after the transaction has been aborted.

Comment by Jan Lindström (Inactive) [ 2017-05-10 ]

commit f4df8c00c957146f04db031f1f9f80aab229d1d2
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Wed May 10 23:13:06 2017 +0300

MDEV-11197: TrxInInnoDB::is_aborted(const trx_t*): Assertion `srv_read_only_mode || trx->in_depth > 0' failed

TrxInInnoDB should be constructed to track if a transaction is executing
inside InnoDB code i.e. it is like a gate between Server and InnoDB
::rnd_next() is called from Server and thus construct TrxInInnoDB
also there.

Applied suggested clean-up to TrxInInnoDB class functions enter()
and exit(). Note that exactly original did not work for enter().

Generated at Thu Feb 08 07:48:03 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.