[MDEV-24455] Assertion `!m_freed_space' failed in mtr_t::start Created: 2020-12-20  Updated: 2020-12-21  Resolved: 2020-12-21

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

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: affects-tests, regression

Issue Links:
Problem/Incident
is caused by MDEV-24445 Using innodb_undo_tablespaces corrupt... Closed

 Description    

--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (a TEXT, b TEXT) ENGINE=InnoDB PAGE_COMPRESSED='ON';
 
INSERT INTO t1 VALUES(REPEAT('x',81),REPEAT('x',8034));
 
DELETE FROM t1;
 
 
 
# Cleanup
 
DROP TABLE t1;

10.5 0c23e32d27

 
mariadbd: /data/src/10.5/storage/innobase/mtr/mtr0mtr.cc:357: void mtr_t::start(): Assertion `!m_freed_space' failed.
 
201220 20:51:13 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f9ea7e94f36 in __GI___assert_fail (assertion=0x557bd41dcd92 "!m_freed_space", file=0x557bd41dca18 "/data/src/10.5/storage/innobase/mtr/mtr0mtr.cc", line=357, function=0x557bd41dcd7e "void mtr_t::start()") at assert.c:101
 
#8  0x0000557bd39bb378 in mtr_t::start (this=0x7f9e927fa630) at /data/src/10.5/storage/innobase/mtr/mtr0mtr.cc:357
 
#9  0x0000557bd3ba32c2 in btr_free_externally_stored_field (index=0x7f9e6c0fa538, field_ref=0x7f9ea19d80e5 "", rec=0x7f9ea19d8081 "", offsets=0x7f9e7c009e08, block=0x7f9ea14ef288, i=4, rollback=false, local_mtr=0x7f9e927fb140) at /data/src/10.5/storage/innobase/btr/btr0cur.cc:7672
 
#10 0x0000557bd3ba3c1e in btr_rec_free_externally_stored_fields (index=0x7f9e6c0fa538, rec=0x7f9ea19d8081 "", offsets=0x7f9e7c009e08, block=0x7f9ea14ef288, rollback=false, mtr=0x7f9e927fb140) at /data/src/10.5/storage/innobase/btr/btr0cur.cc:7804
 
#11 0x0000557bd3b9d8af in btr_cur_pessimistic_delete (err=0x7f9e927faebc, has_reserved_extents=0, cursor=0x557bd71a8f48, flags=0, rollback=false, mtr=0x7f9e927fb140) at /data/src/10.5/storage/innobase/btr/btr0cur.cc:5689
 
#12 0x0000557bd3a9f6c2 in row_purge_remove_clust_if_poss_low (node=0x557bd71a8ea8, mode=65569) at /data/src/10.5/storage/innobase/row/row0purge.cc:143
 
#13 0x0000557bd3a9f7f4 in row_purge_remove_clust_if_poss (node=0x557bd71a8ea8) at /data/src/10.5/storage/innobase/row/row0purge.cc:192
 
#14 0x0000557bd3aa0a60 in row_purge_del_mark (node=0x557bd71a8ea8) at /data/src/10.5/storage/innobase/row/row0purge.cc:646
 
#15 0x0000557bd3aa244b in row_purge_record_func (node=0x557bd71a8ea8, undo_rec=0x557bd71b7578 "", thr=0x557bd71a8cc8, updated_extern=false) at /data/src/10.5/storage/innobase/row/row0purge.cc:1047
 
#16 0x0000557bd3aa270d in row_purge (node=0x557bd71a8ea8, undo_rec=0x557bd71b7578 "", thr=0x557bd71a8cc8) at /data/src/10.5/storage/innobase/row/row0purge.cc:1108
 
#17 0x0000557bd3aa288d in row_purge_step (thr=0x557bd71a8cc8) at /data/src/10.5/storage/innobase/row/row0purge.cc:1157
 
#18 0x0000557bd3a0f270 in que_thr_step (thr=0x557bd71a8cc8) at /data/src/10.5/storage/innobase/que/que0que.cc:947
 
#19 0x0000557bd3a0f508 in que_run_threads_low (thr=0x557bd71a8cc8) at /data/src/10.5/storage/innobase/que/que0que.cc:1009
 
#20 0x0000557bd3a0f76e in que_run_threads (thr=0x557bd71a8cc8) at /data/src/10.5/storage/innobase/que/que0que.cc:1049
 
#21 0x0000557bd3ae7f12 in srv_task_execute () at /data/src/10.5/storage/innobase/srv/srv0srv.cc:1910
 
#22 0x0000557bd3ae8721 in purge_worker_callback () at /data/src/10.5/storage/innobase/srv/srv0srv.cc:2073
 
#23 0x0000557bd3cf96fa in tpool::task_group::execute (this=0x557bd5330fe0 <purge_task_group>, t=0x557bd5330d60 <purge_worker_task>) at /data/src/10.5/tpool/task_group.cc:55
 
#24 0x0000557bd3cf9a76 in tpool::task::execute (this=0x557bd5330d60 <purge_worker_task>) at /data/src/10.5/tpool/task.cc:47
 
#25 0x0000557bd3cf203d in tpool::thread_pool_generic::worker_main (this=0x557bd6fef250, thread_var=0x557bd6ffed70) at /data/src/10.5/tpool/tpool_generic.cc:546
 
#26 0x0000557bd3cf9502 in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=@0x557bd71baa98: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x557bd3cf1fa4 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x557bd71baa90: 0x557bd6fef250) at /usr/include/c++/9/bits/invoke.h:73
 
#27 0x0000557bd3cf93e4 in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=@0x557bd71baa98: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x557bd3cf1fa4 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/9/bits/invoke.h:95
 
#28 0x0000557bd3cf9303 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x557bd71baa88) at /usr/include/c++/9/thread:244
 
#29 0x0000557bd3cf929e in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x557bd71baa88) at /usr/include/c++/9/thread:251
 
#30 0x0000557bd3cf927e in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x557bd71baa80) at /usr/include/c++/9/thread:195
 
#31 0x00007f9ea8290d84 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
 
#32 0x00007f9ea83ac609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#33 0x00007f9ea7f80293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

The failure started happening on 10.5 after the commit below, but that could be just because the commit introduced the assertion. I have no information whether it's a wrong assertion or there is an underlying problem, and if it's the latter, whether it existed before the patch.

commit 0c23e32d27a11bae6dd38703eba674ef6eeb34f4 (origin/HEAD, origin/10.5, 10.5)
 
Author: Marko Mäkelä
 
Date:   Fri Dec 18 17:12:57 2020 +0200
 
 
 
    MDEV-24445 Using innodb_undo_tablespaces corrupts system tablespace



 Comments   
Comment by Marko Mäkelä [ 2020-12-21 ]

Yes, this definitely should be caused by MDEV-24445, because that change introduced the data member mtr_t::m_freed_space to augment mtr_t::m_freed_pages.

Comment by Marko Mäkelä [ 2020-12-21 ]

For some reason, I was not able to reproduce this under rr record, even though this seemed to reproduce deterministically each time outside it. In one place, the new data member was not cleared in sync with the pre-existing one:

diff --git a/storage/innobase/mtr/mtr0mtr.cc b/storage/innobase/mtr/mtr0mtr.cc
 
index 2f29e4bff89..f7bde06544f 100644
 
--- a/storage/innobase/mtr/mtr0mtr.cc
 
+++ b/storage/innobase/mtr/mtr0mtr.cc
 
@@ -433,6 +433,7 @@ void mtr_t::commit()
 
         m_freed_space->clear_freed_ranges();
 
       delete m_freed_pages;
 
       m_freed_pages= nullptr;
 
+      m_freed_space= nullptr;
 
       /* mtr_t::start() will reset m_trim_pages */
 
     }
 
     else

Comment by Marko Mäkelä [ 2020-12-21 ]

Here is a more deterministic test that also repeats the problem under rr record:

--source include/have_innodb.inc
 
CREATE TABLE t1 (a TEXT, b TEXT) ENGINE=InnoDB PAGE_COMPRESSED='ON';
 
BEGIN; INSERT INTO t1 VALUES(REPEAT('x',81),REPEAT('x',8034)); ROLLBACK;
 
DROP TABLE t1;

The original test involves a race condition between DROP TABLE and the purge of the DELETE. The above is a single-threaded test, with ROLLBACK triggering the assertion failure.

Comment by Elena Stepanova [ 2020-12-21 ]

The same assertion failure has also been observed with a different stack trace in the tests. I don't have a test case for this variation yet, so I can't verify whether it goes away after the patch.

10.5 0c23e32d

 
mysqld: /home/elenst/src/10.5/storage/innobase/mtr/mtr0mtr.cc:357: void mtr_t::start(): Assertion `!m_freed_space' failed.
 
201220  7:57:21 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007fe1cbfad252 in __assert_fail () from /lib64/libc.so.6
 
#8  0x000055ae90649692 in mtr_t::start (this=0x7fe1c8257780) at /home/elenst/src/10.5/storage/innobase/mtr/mtr0mtr.cc:357
 
#9  0x000055ae9071c264 in row_log_table_apply_delete_low (pcur=0x7fe1c8257680, offsets=0x7fe0f432e758, heap=0x7fe0f436ed78, mtr=0x7fe1c8257780) at /home/elenst/src/10.5/storage/innobase/row/row0log.cc:1873
 
#10 0x000055ae9071ceb6 in row_log_table_apply_delete (trx_id_col=1, mrec=0x7fe1c80c8003 "\200", moffsets=0x7fe0f434a458, offsets_heap=0x7fe0f432e6d8, heap=0x7fe0f436ed78, log=0x7fe0f43aa4f8) at /home/elenst/src/10.5/storage/innobase/row/row0log.cc:2032
 
#11 0x000055ae9071ed1e in row_log_table_apply_op (thr=0x7fe0f411bff8, new_trx_id_col=1, dup=0x7fe1c8257fa0, error=0x7fe1c8257d54, offsets_heap=0x7fe0f432e6d8, heap=0x7fe0f436ed78, mrec=0x7fe1c80c8003 "\200", mrec_end=0x7fe1c80c8030 "", offsets=0x7fe0f434a458) at /home/elenst/src/10.5/storage/innobase/row/row0log.cc:2515
 
#12 0x000055ae90721855 in row_log_table_apply_ops (thr=0x7fe0f411bff8, dup=0x7fe1c8257fa0, stage=0x7fe0f4249e08) at /home/elenst/src/10.5/storage/innobase/row/row0log.cc:3040
 
#13 0x000055ae90721fa1 in row_log_table_apply (thr=0x7fe0f411bff8, old_table=0x7fe1684968a8, table=0x7fe1c82595b0, stage=0x7fe0f4249e08, new_table=0x7fe0f42cce98) at /home/elenst/src/10.5/storage/innobase/row/row0log.cc:3146
 
#14 0x000055ae905a910e in alter_rebuild_apply_log (ctx=0x7fe0f4016538, ha_alter_info=0x7fe1c8259510, altered_table=0x7fe1c82595b0) at /home/elenst/src/10.5/storage/innobase/handler/handler0alter.cc:10706
 
#15 0x000055ae905aa056 in ha_innobase::commit_inplace_alter_table (this=0x7fe16848c930, altered_table=0x7fe1c82595b0, ha_alter_info=0x7fe1c8259510, commit=true) at /home/elenst/src/10.5/storage/innobase/handler/handler0alter.cc:10906
 
#16 0x000055ae9009a0a1 in handler::ha_commit_inplace_alter_table (this=0x7fe16848c930, altered_table=0x7fe1c82595b0, ha_alter_info=0x7fe1c8259510, commit=true) at /home/elenst/src/10.5/sql/handler.cc:4848
 
#17 0x000055ae8fe243fc in mysql_inplace_alter_table (thd=0x7fe0f4000b18, table_list=0x7fe0f4012698, table=0x7fe1684890f8, altered_table=0x7fe1c82595b0, ha_alter_info=0x7fe1c8259510, target_mdl_request=0x7fe1c8259980, alter_ctx=0x7fe1c825a4d0) at /home/elenst/src/10.5/sql/sql_table.cc:8107
 
#18 0x000055ae8fe2bba5 in mysql_alter_table (thd=0x7fe0f4000b18, new_db=0x55ae90ac6be0 <null_clex_str>, new_name=0x55ae90ac6be0 <null_clex_str>, create_info=0x7fe1c825b0c0, table_list=0x7fe0f4012698, alter_info=0x7fe1c825aff0, order_num=0, order=0x0, ignore=false, if_exists=false) at /home/elenst/src/10.5/sql/sql_table.cc:10653
 
#19 0x000055ae8fe2f176 in mysql_recreate_table (thd=0x7fe0f4000b18, table_list=0x7fe0f4012698, table_copy=false) at /home/elenst/src/10.5/sql/sql_table.cc:11613
 
#20 0x000055ae8feddaa3 in admin_recreate_table (thd=0x7fe0f4000b18, table_list=0x7fe0f4012698) at /home/elenst/src/10.5/sql/sql_admin.cc:58
 
#21 0x000055ae8fee0f46 in mysql_admin_table(THD *, TABLE_LIST *, HA_CHECK_OPT *, const char *, thr_lock_type, bool, bool, uint, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *), struct {...}, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *)) (thd=0x7fe0f4000b18, tables=0x7fe0f4012698, check_opt=0x7fe0f4005f48, operator_name=0x55ae90b25f90 "optimize", lock_type=TL_WRITE, org_open_for_modify=true, repair_table_use_frm=false, extra_open_options=0, prepare_func=0x0, operator_func=(int (handler::*)(handler * const, THD *, HA_CHECK_OPT *)) 0x55ae90099928 <handler::ha_optimize(THD*, st_ha_check_opt*)>, view_operator_func=0x0) at /home/elenst/src/10.5/sql/sql_admin.cc:1098
 
#22 0x000055ae8fee2339 in Sql_cmd_optimize_table::execute (this=0x7fe0f4012d70, thd=0x7fe0f4000b18) at /home/elenst/src/10.5/sql/sql_admin.cc:1450
 
#23 0x000055ae8fd2cb83 in mysql_execute_command (thd=0x7fe0f4000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:6006
 
#24 0x000055ae8fd32bd1 in mysql_parse (thd=0x7fe0f4000b18, rawbuf=0x7fe0f4012590 "OPTIMIZE /* QNO 2255 CON_ID 8 */ TABLE `tc032`", length=46, parser_state=0x7fe1c825c3e0, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:8042
 
#25 0x000055ae8fd1ed1c in dispatch_command (command=COM_QUERY, thd=0x7fe0f4000b18, packet=0x7fe0f40086a9 "", packet_length=46, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:1873
 
#26 0x000055ae8fd1d390 in do_command (thd=0x7fe0f4000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:1354
 
#27 0x000055ae8fec8b6f in do_handle_one_connection (connect=0x55ae92f673e8, put_in_cache=true) at /home/elenst/src/10.5/sql/sql_connect.cc:1410
 
#28 0x000055ae8fec88b3 in handle_one_connection (arg=0x55ae92f673e8) at /home/elenst/src/10.5/sql/sql_connect.cc:1312
 
#29 0x000055ae90415c14 in pfs_spawn_thread (arg=0x55ae92e769c8) at /home/elenst/src/10.5/storage/perfschema/pfs.cc:2201
 
#30 0x00007fe1cdec6ea5 in start_thread () from /lib64/libpthread.so.0
 
#31 0x00007fe1cc07c8dd in clone () from /lib64/libc.so.6

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