[MDEV-23132] Assertion `trn->locked_tables == 0 && trn->used_instances == 0' failed in trnman_end_trn Created: 2020-07-09  Updated: 2023-11-28

Status: Confirmed
Project: MariaDB Server
Component/s: Storage Engine - Aria
Affects Version/s: 10.5, 10.6, 10.7, 10.8, 10.9, 10.10
Fix Version/s: 10.5, 10.6

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Michael Widenius
Resolution: Unresolved Votes: 0
Labels: None

Attachments: File 23132.7z    

 Description   

10.5 55c7536a0268f65d8ffcdb93

 
 [ERROR] mysqld got signal 11 ;
 
Server version: 10.5.5-MariaDB-log
 
 
 
maria/ma_trnman.h:72(_ma_reset_trn_for_table)[0x5593bc4ad073]
 
maria/ha_maria.cc:3458(maria_commit(handlerton*, THD*, bool))[0x5593bc3018ee]
 
sql/handler.cc:1936(commit_one_phase_2(THD*, bool, THD_TRANS*, bool))[0x5593bc30f0dd]
 
sql/handler.cc:1716(ha_commit_trans(THD*, bool))[0x5593bc2139e3]
 
sql/transaction.cc:472(trans_commit_stmt(THD*))[0x5593bc1210fb]
 
sql/sql_class.h:4038(mysql_execute_command(THD*))[0x5593bc114092]
 
sql/sql_parse.cc:8010(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x5593bc11ebf7]
 
sql/sql_parse.cc:1869(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x5593bc11fb4d]
 
sql/sql_parse.cc:1347(do_command(THD*))[0x5593bc2058f0]
 
sql/sql_connect.cc:1411(do_handle_one_connection(CONNECT*, bool))[0x5593bc205cbd]
 
sql/sql_connect.cc:1313(handle_one_connection)[0x5593bc52f2db]
 
nptl/pthread_create.c:487(start_thread)[0x7f5f4b854fa3]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f5f4ae5d4cf]


mysqld: /10.5/storage/maria/trnman.c:416: trnman_end_trn: Assertion `trn->locked_tables == 0 && trn->used_instances == 0' failed.
 
 [ERROR] mysqld got signal 6 ;
 
 
 
Server version: 10.5.5-MariaDB-debug-log
 
linux/raise.c:51(__GI_raise)[0x7f887c7ef535]
 
stdlib/abort.c:81(__GI_abort)[0x7f887c7ef40f]
 
intl/loadmsgcat.c:1177(_nl_load_domain)[0x7f887c7fd102]
 
maria/trnman.c:417(trnman_end_trn)[0x5581adba6406]
 
maria/ha_maria.cc:2864(ha_maria::external_lock(THD*, int))[0x5581ad5609b7]
 
sql/handler.cc:6656(handler::ha_external_lock(THD*, int))[0x5581ad00d36e]
 
sql/handler.h:3408(handler::ha_external_unlock(THD*))[0x5581ad85391a]
 
sql/lock.cc:727(unlock_external(THD*, TABLE**, unsigned int))[0x5581ad85113d]
 
sql/lock.cc:432(mysql_unlock_tables(THD*, st_mysql_lock*, bool))[0x5581ad850f83]
 
sql/lock.cc:418(mysql_unlock_tables(THD*, st_mysql_lock*))[0x5581acc5ba87]
 
sql/sql_class.cc:5783(THD::commit_whole_transaction_and_close_tables())[0x5581ad9822ae]
 
sql/sp.cc:776(Sp_handler::db_find_routine(THD*, Database_qualified_name const*, sp_head**) const)[0x5581ad982451]
 
sql/sp.cc:787(Sp_handler::db_find_and_cache_routine(THD*, Database_qualified_name const*, sp_head**) const)[0x5581ad9910b4]
 
sql/sp.cc:2833(Sp_handler::sp_cache_routine(THD*, Database_qualified_name const*, bool, sp_head**) const)[0x5581ad990c69]
 
sql/sp.cc:2786(Sroutine_hash_entry::sp_cache_routine(THD*, bool, sp_head**) const)[0x5581acbd7284]
 
sql/sql_base.cc:3404(open_and_process_routine(THD*, Query_tables_list*, Sroutine_hash_entry*, Prelocking_strategy*, bool, Open_table_context*, bool*, bool*))[0x5581acbdc202]
 
sql/sql_base.cc:4328(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*))[0x5581acbb281e]
 
sql/sql_base.h:477(open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int))[0x5581ad04e615]
 
sql/sql_update.cc:401(mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, bool, unsigned long long*, unsigned long long*))[0x5581acd69871]
 
sql/sql_parse.cc:4393(mysql_execute_command(THD*))[0x5581acd826c6]
 
sql/sql_parse.cc:7993(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x5581acd595df]
 
sql/sql_parse.cc:1869(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x5581acd55ef7]
 
sql/sql_parse.cc:1347(do_command(THD*))[0x5581ad17a67d]
 
sql/sql_connect.cc:1411(do_handle_one_connection(CONNECT*, bool))[0x5581ad179fda]
 
sql/sql_connect.cc:1315(handle_one_connection)[0x5581ade30f0a]
 
nptl/pthread_create.c:487(start_thread)[0x7f887d2bffa3]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f887c8c64cf]
 
 
 
Query (0x62b0001a42a8): UPDATE `view_table10_aria_int_autoinc` SET `col_int_key` = RAND() WHERE `col_int_key` = NULL ORDER BY RAND ()



 Comments   
Comment by Alice Sherepa [ 2020-11-03 ] 

mysqld: /10.5/storage/maria/ha_maria.cc:1241: virtual int ha_maria::close(): Assertion `file->trn_next == 0 && file->trn_prev == 0' failed.
 
201013  9:14:44 [ERROR] mysqld got signal 6 ;
 
 
 
Server version: 10.5.7-MariaDB-debug-log
 
 
 
linux/raise.c:51(__GI_raise)[0x7fbe8ed21535]
 
stdlib/abort.c:81(__GI_abort)[0x7fbe8ed2140f]
 
intl/loadmsgcat.c:1177(_nl_load_domain)[0x7fbe8ed2f102]
 
maria/ha_maria.cc:1242(ha_maria::close())[0x558cc2b2e7eb]
 
sql/handler.cc:3048(handler::ha_close())[0x558cc268852f]
 
sql/table.cc:4310(closefrm(TABLE*))[0x558cc296c196]
 
sql/table_cache.cc:221(intern_close_table(TABLE*))[0x558cc29740a9]
 
sql/table_cache.cc:1292(TDC_element::flush_unused(bool))[0x558cc2973ce9]
 
sql/table_cache.cc:1259(TDC_element::flush(THD*, bool))[0x558cc21acced]
 
sql/sql_base.cc:1318(wait_while_table_is_used(THD*, TABLE*, ha_extra_function))[0x558cc25e3756]
 
sql/sql_table.cc:9588(simple_rename_or_index_change(THD*, TABLE_LIST*, Alter_info::enum_enable_or_disable, Alter_table_ctx*))[0x558cc25e7e89]
 
sql/sql_table.cc:10246(mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool, bool))[0x558cc277e896]
 
sql/sql_alter.cc:534(Sql_cmd_alter_table::execute(THD*))[0x558cc23578e5]
 
sql/sql_parse.cc:5952(mysql_execute_command(THD*))[0x558cc2364f14]
 
sql/sql_parse.cc:7994(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558cc233c885]
 
sql/sql_parse.cc:1870(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x558cc2338747]
 
sql/sql_parse.cc:1348(do_command(THD*))[0x558cc2762e82]
 
sql/sql_connect.cc:1410(do_handle_one_connection(CONNECT*, bool))[0x558cc27627df]
 
sql/sql_connect.cc:1314(handle_one_connection)[0x558cc3420be2]
 
nptl/pthread_create.c:487(start_thread)[0x7fbe8f7f1fa3]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7fbe8edf84cf]
 
 
 
Query (0x62b0000d2391): ALTER TABLE D DISABLE KEYS

Comment by Elena Stepanova [ 2021-01-15 ]

Concurrent test for the failures from the description (I'm not convinced that the one in the comment above is related, other than them both being about Aria):

git clone https://github.com/MariaDB/randgen --branch mdev23132 rqg-mdev23132
 
cd rqg-mdev23132
 
. ./mdev23132.cmd <basedir>

10.5 deadec4e debug

 
mysqld: /data/src/10.5/storage/maria/trnman.c:416: trnman_end_trn: Assertion `trn->locked_tables == 0 && trn->used_instances == 0' failed.
 
210115 21:28:21 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f9d6397df36 in __GI___assert_fail (assertion=0x55f3ace8d7f8 "trn->locked_tables == 0 && trn->used_instances == 0", file=0x55f3ace8d3c0 "/data/src/10.5/storage/maria/trnman.c", line=416, function=0x55f3ace8da48 <__PRETTY_FUNCTION__.14913> "trnman_end_trn") at assert.c:101
 
#8  0x000055f3ac47145f in trnman_end_trn (trn=0x7f9d089c3bf8, commit=0 '\000') at /data/src/10.5/storage/maria/trnman.c:416
 
#9  0x000055f3ac4abd6f in ma_commit (trn=0x7f9d089c3bf8) at /data/src/10.5/storage/maria/ma_commit.c:39
 
#10 0x000055f3ac46bb28 in ha_maria::external_lock (this=0x7f9d191e60b0, thd=0x7f9d04000db8, lock_type=2) at /data/src/10.5/storage/maria/ha_maria.cc:2871
 
#11 0x000055f3ac1d5d5a in handler::ha_external_lock (this=0x7f9d191e60b0, thd=0x7f9d04000db8, lock_type=2) at /data/src/10.5/sql/handler.cc:6677
 
#12 0x000055f3abf67886 in handler::ha_external_unlock (this=0x7f9d191e60b0, thd=0x7f9d04000db8) at /data/src/10.5/sql/handler.h:3410
 
#13 0x000055f3ac31d318 in unlock_external (thd=0x7f9d04000db8, table=0x7f9d06ee0280, count=1) at /data/src/10.5/sql/lock.cc:727
 
#14 0x000055f3ac31c62e in mysql_unlock_tables (thd=0x7f9d04000db8, sql_lock=0x7f9d06ee0250, free_lock=false) at /data/src/10.5/sql/lock.cc:432
 
#15 0x000055f3ac31c57b in mysql_unlock_tables (thd=0x7f9d04000db8, sql_lock=0x7f9d06ee0250) at /data/src/10.5/sql/lock.cc:415
 
#16 0x000055f3abde5a8b in THD::commit_whole_transaction_and_close_tables (this=0x7f9d04000db8) at /data/src/10.5/sql/sql_class.cc:5876
 
#17 0x000055f3ac393927 in Sp_handler::db_find_routine (this=0x55f3ad60c200 <sp_handler_procedure>, thd=0x7f9d04000db8, name=0x7f9d60210640, sphp=0x7f9d60210858) at /data/src/10.5/sql/sp.cc:775
 
#18 0x000055f3ac393a11 in Sp_handler::db_find_and_cache_routine (this=0x55f3ad60c200 <sp_handler_procedure>, thd=0x7f9d04000db8, name=0x7f9d60210640, sp=0x7f9d60210858) at /data/src/10.5/sql/sp.cc:787
 
#19 0x000055f3ac399c12 in Sp_handler::sp_cache_routine (this=0x55f3ad60c200 <sp_handler_procedure>, thd=0x7f9d04000db8, name=0x7f9d60210640, lookup_only=false, sp=0x7f9d60210858) at /data/src/10.5/sql/sp.cc:2829
 
#20 0x000055f3ac399a01 in Sroutine_hash_entry::sp_cache_routine (this=0x7f9d0584bf00, thd=0x7f9d04000db8, lookup_only=false, sp=0x7f9d60210858) at /data/src/10.5/sql/sp.cc:2782
 
#21 0x000055f3abdae405 in open_and_process_routine (thd=0x7f9d04000db8, prelocking_ctx=0x7f9d04004e98, rt=0x7f9d0584bf00, prelocking_strategy=0x7f9d60210a58, has_prelocking_list=false, ot_ctx=0x7f9d60210940, need_prelocking=0x7f9d602108e3, routine_modifies_data=0x7f9d602108e4) at /data/src/10.5/sql/sql_base.cc:3421
 
#22 0x000055f3abdb0586 in open_tables (thd=0x7f9d04000db8, options=..., start=0x7f9d602109b8, counter=0x7f9d602109d4, flags=0, prelocking_strategy=0x7f9d60210a58) at /data/src/10.5/sql/sql_base.cc:4347
 
#23 0x000055f3abdb237b in open_and_lock_tables (thd=0x7f9d04000db8, options=..., tables=0x7f9d04012b88, derived=true, flags=0, prelocking_strategy=0x7f9d60210a58) at /data/src/10.5/sql/sql_base.cc:5211
 
#24 0x000055f3abd6806d in open_and_lock_tables (thd=0x7f9d04000db8, tables=0x7f9d04012b88, derived=true, flags=0) at /data/src/10.5/sql/sql_base.h:507
 
#25 0x000055f3abe06d5b in mysql_insert (thd=0x7f9d04000db8, table_list=0x7f9d04012b88, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0) at /data/src/10.5/sql/sql_insert.cc:756
 
#26 0x000055f3abe5b596 in mysql_execute_command (thd=0x7f9d04000db8) at /data/src/10.5/sql/sql_parse.cc:4596
 
#27 0x000055f3abe672b0 in mysql_parse (thd=0x7f9d04000db8, rawbuf=0x7f9d04012a70 "INSERT INTO t2 ( f ) VALUES ( 4 ) /* QNO 4367 CON_ID 9 */", length=57, parser_state=0x7f9d60211510, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:8062
 
#28 0x000055f3abe53237 in dispatch_command (command=COM_QUERY, thd=0x7f9d04000db8, packet=0x7f9d04008f99 "INSERT INTO t2 ( f ) VALUES ( 4 ) /* QNO 4367 CON_ID 9 */ ", packet_length=58, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1889
 
#29 0x000055f3abe51a2b in do_command (thd=0x7f9d04000db8) at /data/src/10.5/sql/sql_parse.cc:1370
 
#30 0x000055f3abfff78d in do_handle_one_connection (connect=0x55f3aef04868, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1410
 
#31 0x000055f3abfff4f0 in handle_one_connection (arg=0x55f3aef04868) at /data/src/10.5/sql/sql_connect.cc:1312
 
#32 0x000055f3ac55e45d in pfs_spawn_thread (arg=0x55f3aee0b608) at /data/src/10.5/storage/perfschema/pfs.cc:2201
 
#33 0x00007f9d63e95609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#34 0x00007f9d63a69293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.5 deadec4e non-debug ASAN

 
210115 21:50:23 [ERROR] mysqld got signal 11 ;
 
 
 
sigaction.c:0(__restore_rt)[0x7f40d50843c0]
 
maria/ma_trnman.h:73(reset_thd_trn(THD*, st_maria_handler*))[0x55d96e51cc86]
 
maria/ha_maria.cc:3469(maria_commit(handlerton*, THD*, bool))[0x55d96e51d6f2]
 
sql/handler.cc:1941(commit_one_phase_2(THD*, bool, THD_TRANS*, bool))[0x55d96de416c7]
 
sql/handler.cc:1714(ha_commit_trans(THD*, bool))[0x55d96de4c44a]
 
sql/sql_class.cc:5874(THD::commit_whole_transaction_and_close_tables())[0x55d96d61e4ae]
 
sql/sp.cc:776(Sp_handler::db_find_routine(THD*, Database_qualified_name const*, sp_head**) const)[0x55d96e34b8d4]
 
sql/sp.cc:787(Sp_handler::db_find_and_cache_routine(THD*, Database_qualified_name const*, sp_head**) const)[0x55d96e34bc9e]
 
sql/sp.cc:2829(Sp_handler::sp_cache_routine(THD*, Database_qualified_name const*, bool, sp_head**) const)[0x55d96e34beb0]
 
sql/sp.cc:2771(Sroutine_hash_entry::sp_cache_routine(THD*, bool, sp_head**) const)[0x55d96e3576f3]
 
sql/sql_base.cc:3421(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*))[0x55d96d5d1087]
 
sql/sql_base.cc:5211(open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*))[0x55d96d5d3232]
 
sql/sql_base.h:395(open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int))[0x55d96d67ba85]
 
sql/sql_parse.cc:4596(mysql_execute_command(THD*))[0x55d96d74eb84]
 
sql/sql_parse.cc:8079(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x55d96d714b1d]
 
sql/sql_parse.cc:1892(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x55d96d740ebe]
 
sql/sql_parse.cc:1370(do_command(THD*))[0x55d96d746d52]
 
sql/sql_connect.cc:1410(do_handle_one_connection(CONNECT*, bool))[0x55d96dae750d]
 
sql/sql_connect.cc:1312(handle_one_connection)[0x55d96dae80a5]
 
perfschema/pfs.cc:2204(pfs_spawn_thread)[0x55d96e6d6349]
 
nptl/pthread_create.c:478(start_thread)[0x7f40d5078609]
 
??:0(clone)[0x7f40d4c4e293]

The debug assertion happens for me within a few minutes. The non-debug crash is extremely rare.

Command line (same as mdev23132.cmd in the git branch):

perl ./runall-trials.pl --trials=5 --threads=5 --duration=300 --mysqld=--max-statement-time=5 --mysqld=--lock-wait-timeout=3 --grammar=mdev23132.yy --skip-gendata --seed=1610588500 --vardir1=/dev/shm/var_mdev23132 --basedir1=$1

Grammar (same as mdev23132.yy in the git branch):

query_init:
 
    CREATE TABLE IF NOT EXISTS t1 (f INT, KEY(f)) ENGINE=Aria
 
  ; CREATE TABLE IF NOT EXISTS t2 (f INT, KEY(f)) ENGINE=Aria
 
  ; CREATE TABLE IF NOT EXISTS t3 (f INT, KEY(f)) ENGINE=Aria
 
  ; INSERT INTO t2 VALUES (0)
 
  ; INSERT INTO t3 VALUES (NULL),(9)
 
;
 
 
 
my_table:
 
  t1 | t2 | t3 ;
 
 
 
query:
 
  binlog_event | binlog_event | binlog_event | binlog_event | binlog_event |
 
  binlog_event | binlog_event | binlog_event | binlog_event | binlog_event |
 
  binlog_event | binlog_event | binlog_event | binlog_event | binlog_event |
 
  binlog_event | binlog_event | binlog_event | binlog_event | binlog_event | create_trigger ;
 
 
 
binlog_event:
 
  dml | dml | dml |  xid_event ;
 
 
 
dml:
 
  delete | insert | update ;
 
 
 
xid_event:
 
  START TRANSACTION | COMMIT | ROLLBACK |
 
  SET AUTOCOMMIT = ON | SET AUTOCOMMIT = OFF ;
 
 
 
insert:
 
  INSERT INTO my_table ( f ) VALUES ( _digit ) ;
 
 
 
update:
 
  UPDATE my_table SET f = _digit WHERE f < _digit ORDER BY f LIMIT _digit ;
 
 
 
delete:
 
  DELETE FROM my_table ORDER BY f LIMIT 1 ;
 
 
 
create_trigger:
 
  CREATE TRIGGER _letter trigger_time trigger_event ON my_table FOR EACH ROW BEGIN trigger_body ; END ;
 
 
 
trigger_time:
 
  BEFORE | AFTER ;
 
 
 
trigger_event:
 
  INSERT | UPDATE ;
 
 
 
trigger_body:
 
  dml ; dml ; dml ; CALL _letter ;

Could not reproduce within reasonable time on 10.4.
Could not reproduce with rr.

Comment by Alice Sherepa [ 2023-02-01 ] 

230201 12:06:50 [ERROR] mysqld got signal 11 ;
 
 
 
Server version: 10.6.12-MariaDB-debug-log source revision: 0e737f78980fcfe83b05c27215eb3f5ede1ea473
 
 
 
maria/ma_trnman.h:73(_ma_reset_trn_for_table(st_maria_handler*))[0x562fa4fb236e]
 
maria/ha_maria.cc:3054(reset_thd_trn(THD*, st_maria_handler*))[0x562fa4fc9ed3]
 
maria/ha_maria.cc:3577(maria_commit(handlerton*, THD*, bool))[0x562fa4fcdca1]
 
sql/handler.cc:2087(commit_one_phase_2(THD*, bool, THD_TRANS*, bool))[0x562fa4971859]
 
sql/handler.cc:2040(ha_commit_one_phase(THD*, bool))[0x562fa4971416]
 
sql/handler.cc:1834(ha_commit_trans(THD*, bool))[0x562fa496f76d]
 
sql/transaction.cc:472(trans_commit_stmt(THD*))[0x562fa45a3693]
 
sql/sql_parse.cc:6061(mysql_execute_command(THD*, bool))[0x562fa412628e]
 
sql/sql_parse.cc:8019(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x562fa4132be2]
 
sql/sql_parse.cc:1898(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool))[0x562fa4109495]
 
sql/sql_parse.cc:1409(do_command(THD*, bool))[0x562fa41061a1]
 
sql/sql_connect.cc:1416(do_handle_one_connection(CONNECT*, bool))[0x562fa45603ee]
 
sql/sql_connect.cc:1320(handle_one_connection)[0x562fa455fd44]
 
perfschema/pfs.cc:2203(pfs_spawn_thread)[0x562fa524f159]
 
nptl/pthread_create.c:487(start_thread)[0x7fb2d55abfa3]
 
x86_64/clone.S:97(clone)[0x7fb2d51b706f]

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