[MDEV-21564] Assert in trx_purge_add_update_undo_to_history during shutdown Created: 2020-01-24  Updated: 2020-01-30  Resolved: 2020-01-30

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.31, 10.3.19, 10.4.12, 10.5.1
Fix Version/s: 10.1.45, 10.2.32, 10.3.23, 10.4.13

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: affects-tests

Attachments: File ML13.test    

 Description   

ML13.test
----------------
--source include/have_innodb.inc
 
--disable_abort_on_error
CREATE TABLE t1 (col3 INT, col4 VARCHAR(10)) ENGINE = InnoDB ;
ALTER TABLE t1 ADD FULLTEXT KEY ftidx ( col4 ) ;
INSERT INTO t1 (col3,col4) VALUES (1,'1'), (1,'1')  ;
ALTER TABLE t1 DROP KEY ftidx ;
# Get the assert on shutdown
--error ER_DUP_ENTRY
ALTER TABLE t1 ADD UNIQUE KEY uidx ( col3 ), ADD FULLTEXT KEY ftidx ( col4 ) ;
 
./mtr --mem ML13
Logging: /home/mleich/Server/10.2/mysql-test/mysql-test-run.pl  --mem ML13
...
MariaDB Version 10.2.31-MariaDB-debug
...
==============================================================================
 
TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------
 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
CREATE TABLE t1 (col3 INT, col4 VARCHAR(10)) ENGINE = InnoDB ;
ALTER TABLE t1 ADD FULLTEXT KEY ftidx ( col4 ) ;
Warnings:
Warning 124     InnoDB rebuilding table to add column FTS_DOC_ID
INSERT INTO t1 (col3,col4) VALUES (1,'1'), (1,'1')  ;
ALTER TABLE t1 DROP KEY ftidx ;
ALTER TABLE t1 ADD UNIQUE KEY uidx ( col3 ), ADD FULLTEXT KEY ftidx ( col4 ) ;
ERROR 23000: Duplicate entry '1' for key 'uidx'
***Warnings generated in error logs during shutdown after running tests: main.ML13
 
mysqld: storage/innobase/trx/trx0purge.cc:292: void trx_purge_add_update_undo_to_history(trx_t*, ib_page_t*, mtr_t*): Assertion `srv_undo_sources || trx->undo_no == 0 || ((srv_is_being_started || trx_rollback_or_clean_is_active) && purge_sys->state == PURGE_STATE_INIT) || (srv_force_recovery >= SRV_FORCE_NO_BACKGROUND && purge_sys->state == PURGE_STATE_DISABLED) || ((trx->in_mysql_trx_list || trx->internal) && srv_fast_shutdown)' failed.
Attempting backtrace. You can use the following information to find out
 
mysql-test-run: *** ERROR: Test suite aborted
 
Content of var/log/mysqld.1.err (shortened)
-------------------------------------------
CURRENT_TEST: main.ML13
2020-01-24 19:07:44 140468614063936 [Note] /home/mleich/Server/10.2/bld_debug/sql/mysqld (mysqld 10.2.31-MariaDB-debug-log) starting as process 2290 ...
...
2020-01-24 19:07:44 140468614063936 [Note] /home/mleich/Server/10.2/bld_debug/sql/mysqld: ready for connections.
Version: '10.2.31-MariaDB-debug-log'  socket: '/home/mleich/Server/10.2/bld_debug/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
2020-01-24 19:07:45 140468479891200 [Note] /home/mleich/Server/10.2/bld_debug/sql/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
2020-01-24 19:07:45 140468096587520 [Note] InnoDB: FTS optimize thread exiting.
2020-01-24 19:07:45 140468479891200 [Note] Event Scheduler: Purging the queue. 0 events
mysqld: /home/mleich/Server/10.2/storage/innobase/trx/trx0purge.cc:292: void trx_purge_add_update_undo_to_history(trx_t*, ib_page_t*, mtr_t*): Assertion `srv_undo_sources || trx->undo_no == 0 || ((srv_is_being_started || trx_rollback_or_clean_is_active) && purge_sys->state == PURGE_STATE_INIT) || (srv_force_recovery >= SRV_FORCE_NO_BACKGROUND && purge_sys->state == PURGE_STATE_DISABLED) || ((trx->in_mysql_trx_list || trx->internal) && srv_fast_shutdown)' failed.
200124 19:07:45 [ERROR] mysqld got signal 6 ;
...
Server version: 10.2.31-MariaDB-debug-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=0
....
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x0 thread_stack 0x49000
/home/mleich/Server/10.2/bld_debug/sql/mysqld(my_print_stacktrace+0x38)[0x560a4482fabe]
mysys/stacktrace.c:267(my_print_stacktrace)[0x560a44084a7c]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x13150)[0x7fc164438150]
linux/raise.c:51(__GI_raise)[0x7fc1637890bb]
stdlib/abort.c:92(__GI_abort)[0x7fc16378af5d]
assert/assert.c:92(__assert_fail_base)[0x7fc163780f17]
/lib/x86_64-linux-gnu/libc.so.6(+0x2efc2)[0x7fc163780fc2]
trx/trx0purge.cc:303(trx_purge_add_update_undo_to_history(trx_t*, unsigned char*, mtr_t*))[0x560a44469f53]
trx/trx0undo.cc:1750(trx_undo_update_cleanup(trx_t*, unsigned char*, mtr_t*))[0x560a444a1281]
trx/trx0trx.cc:1421(trx_write_serialisation_history(trx_t*, mtr_t*))[0x560a4449099a]
trx/trx0trx.cc:1881(trx_commit_low(trx_t*, mtr_t*))[0x560a44492242]
trx/trx0trx.cc:1939(trx_commit(trx_t*))[0x560a444923d4]
trx/trx0trx.cc:2163(trx_commit_for_mysql(trx_t*))[0x560a44492c81]
dict/dict0dict.cc:445(dict_table_try_drop_aborted(dict_table_t*, unsigned long, int))[0x560a44544b51]
dict/dict0dict.cc:535(dict_table_close(dict_table_t*, unsigned long, unsigned long))[0x560a44544ea2]
row/row0mysql.cc:1039(row_prebuilt_free(row_prebuilt_t*, unsigned long))[0x560a443d61bd]
handler/ha_innodb.cc:6663(ha_innobase::close())[0x560a442953e8]
sql/handler.cc:2650(handler::ha_close())[0x560a4408b9a7]
sql/table.cc:3490(closefrm(TABLE*))[0x560a43f0e4b6]
sql/table_cache.cc:223(intern_close_table(TABLE*))[0x560a43ffcb1b]
sql/table_cache.cc:334(tc_purge(bool))[0x560a43ffcf3f]
sql/sql_base.cc:376(close_cached_tables(THD*, TABLE_LIST*, bool, unsigned long))[0x560a43d8f746]
sql/table_cache.cc:648(tdc_start_shutdown())[0x560a43ffdfbc]
sql/mysqld.cc:2225(clean_up(bool))[0x560a43d204df]
sql/mysqld.cc:2100(unireg_end())[0x560a43d1ffdf]
sql/mysqld.cc:2026(kill_server(void*))[0x560a43d1fed9]
sql/mysqld.cc:2051(kill_server_thread)[0x560a43d1ff1b]
perfschema/pfs.cc:1864(pfs_spawn_thread)[0x560a447830ab]
nptl/pthread_create.c:465(start_thread)[0x7fc16442c7fc]
x86_64/clone.S:97(clone)[0x7fc163866b5f]
<snip>



 Comments   
Comment by Matthias Leich [ 2020-01-24 ]

Replay on (all binaries compiled with debug)
- 10.2.31 commit 7d313214641241e8ce839d9de01529c2335c620f
- 10.3.19 commit bef843b97f2e91859f2a08845822d619e769f89f
- 10.4.12 commit 983163209d026bfd979b4298053fcbdb373efa9d
- 10.5.1 commit 6af00b2cc620a96372541447cca7134f2d051b19

Comment by Elena Stepanova [ 2020-01-24 ]

A variation of the stack trace that I've been getting in my tests (adding it here for the record and further searches, as I'm removing it from my notes):

10.4 f5390eea

mysqld: /home/vsts/src/storage/innobase/trx/trx0purge.cc:268: void trx_purge_add_undo_to_history(const trx_t*, trx_undo_t*&, mtr_t*): Assertion `srv_undo_sources || trx->undo_no == 0 || (!purge_sys.enabled() && (srv_is_being_started || trx_rollback_is_active || srv_force_recovery >= SRV_FORCE_NO_BACKGROUND)) || ((trx->mysql_thd || trx->internal) && srv_fast_shutdown)' failed.
190718  2:48:46 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
Server version: 10.4.7-MariaDB-debug-log
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=7
max_threads=153
thread_count=10
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467838 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x7f7558001f20
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7f755d213ec0 thread_stack 0x49000
/home/vsts/server/bin/mysqld(my_print_stacktrace+0x40)[0x5582815082f5]
/home/vsts/server/bin/mysqld(handle_fatal_signal+0x3ae)[0x558280d320ad]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f757d86c390]
linux/raise.c:54(__GI_raise)[0x7f757c9be428]
stdlib/abort.c:91(__GI_abort)[0x7f757c9c002a]
assert/assert.c:92(__assert_fail_base)[0x7f757c9b6bd7]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7f757c9b6c82]
/home/vsts/server/bin/mysqld(+0xf50434)[0x55828115f434]
trx/trx0purge.cc:278(trx_purge_add_undo_to_history(trx_t const*, trx_undo_t*&, mtr_t*))[0x55828118560f]
trx/trx0trx.cc:1100(trx_write_serialisation_history(trx_t*, mtr_t*))[0x558281187147]
trx/trx0trx.cc:1528(trx_commit_low(trx_t*, mtr_t*))[0x5582811872a7]
trx/trx0trx.cc:1582(trx_commit(trx_t*))[0x5582811876e8]
trx/trx0trx.cc:1724(trx_commit_for_mysql(trx_t*))[0x5582812e6e73]
fts/fts0sql.cc:276(fts_sql_commit(trx_t*))[0x5582812d946c]
fts/fts0opt.cc:1806(fts_optimize_words(fts_optimize_t*, dict_index_t*, fts_string_t*))[0x5582812d9bc5]
fts/fts0opt.cc:1995(fts_optimize_index(fts_optimize_t*, dict_index_t*))[0x5582812da52d]
fts/fts0opt.cc:2292(fts_optimize_indexes(fts_optimize_t*))[0x5582812da8e1]
fts/fts0opt.cc:2469(fts_optimize_table(dict_table_t*))[0x558280f7aa9e]
handler/ha_innodb.cc:14455(ha_innobase::optimize(THD*, st_ha_check_opt*))[0x558280d407d7]
sql/handler.cc:4460(handler::ha_optimize(THD*, st_ha_check_opt*))[0x558280b80360]
sql/sql_admin.cc:806(mysql_admin_table(THD*, TABLE_LIST*, st_ha_check_opt*, char const*, thr_lock_type, bool, bool, unsigned int, int (*)(THD*, TABLE_LIST*, st_ha_check_opt*), int (handler::*)(THD*, st_ha_check_opt*), int (*)(THD*, TABLE_LIST*, st_ha_check_opt*)))[0x558280b8278a]
sql/sql_parse.cc:6098(mysql_execute_command(THD*))[0x558280a01917]
sql/sql_parse.cc:7908(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x558280a06bce]
sql/sql_parse.cc:1845(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x5582809f2e3c]
sql/sql_parse.cc:1360(do_command(THD*))[0x5582809f1556]
sql/sql_connect.cc:1404(do_handle_one_connection(CONNECT*))[0x558280b6b880]
sql/sql_connect.cc:1307(handle_one_connection)[0x558280b6b5a9]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f757d8626ba]
x86_64/clone.S:111(clone)[0x7f757ca9041d]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f75580130f8): OPTIMIZE TABLE fti_t5 /* QNO 782 CON_ID 16 */
Connection ID (thread ID): 16
Status: KILL_SERVER
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on

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