[MDEV-23145] Server crashes in handler::update_global_table_stats or Assertion `inited == NONE || table->open_by_handler' in handler::ha_external_lock Created: 2020-07-10  Updated: 2023-10-06

Status: Open
Project: MariaDB Server
Component/s: Versioned Tables
Affects Version/s: 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10
Fix Version/s: 10.4, 10.5, 10.6

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Aleksey Midenkov
Resolution: Unresolved Votes: 0
Labels: trx-versioning

Issue Links:
Relates
relates to MDEV-16226 TRX_ID-based System Versioning refact... Stalled
relates to MDEV-16929 Assertion `thd->transaction.stmt.is_e... Stalled
relates to MDEV-25187 Assertion `inited == NONE || table->o... Closed

 Description   

Note: Both failures have been very randomly observed in concurrent tests without changing MAX_SESSION_MEM_USED, it just allows to make a seemingly deterministic test case.

--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (f INT, row_start BIGINT UNSIGNED AS ROW START, row_end BIGINT UNSIGNED AS ROW END, PERIOD FOR SYSTEM_TIME(row_start,row_end)) ENGINE=InnoDB WITH SYSTEM VERSIONING;
 
INSERT INTO t1 () VALUES ();
 
FLUSH TABLES;
 
UPDATE t1 SET f = NULL;
 
SET MAX_SESSION_MEM_USED= @@max_session_mem_used + 1024;
 
SELECT * FROM t1 FOR SYSTEM_TIME AS OF NOW();
 
 
 
# Cleanup
 
DROP TABLE t1;

10.3 non-debug f3f23b5c

 
#3  <signal handler called>
 
#4  0x0000562c903c013f in handler::update_global_table_stats (this=0x7fc69c0cd0f0) at /data/src/10.3/sql/handler.cc:4937
 
#5  0x0000562c9017354d in close_thread_table (thd=thd@entry=0x7fc69c0009a8, table_ptr=table_ptr@entry=0x7fc69c000a88) at /data/src/10.3/sql/sql_base.cc:891
 
#6  0x0000562c9017378b in close_thread_tables (thd=thd@entry=0x7fc69c0009a8) at /data/src/10.3/sql/sql_base.cc:862
 
#7  0x0000562c901d0995 in mysql_execute_command (thd=thd@entry=0x7fc69c0009a8) at /data/src/10.3/sql/sql_parse.cc:6107
 
#8  0x0000562c901d888a in mysql_parse (thd=thd@entry=0x7fc69c0009a8, rawbuf=<optimized out>, length=44, parser_state=parser_state@entry=0x7fc6e80b45f0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.3/sql/sql_parse.cc:7810
 
#9  0x0000562c901da485 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fc69c0009a8, packet=packet@entry=0x7fc69c0070c9 "", packet_length=packet_length@entry=44, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.3/sql/sql_parse.cc:1848
 
#10 0x0000562c901dbf25 in do_command (thd=0x7fc69c0009a8) at /data/src/10.3/sql/sql_parse.cc:1393
 
#11 0x0000562c902b0882 in do_handle_one_connection (connect=connect@entry=0x562c93a10e18) at /data/src/10.3/sql/sql_connect.cc:1403
 
#12 0x0000562c902b09dd in handle_one_connection (arg=arg@entry=0x562c93a10e18) at /data/src/10.3/sql/sql_connect.cc:1308
 
#13 0x0000562c908afbd1 in pfs_spawn_thread (arg=0x562c93a11078) at /data/src/10.3/storage/perfschema/pfs.cc:1869
 
#14 0x00007fc6eef0d4a4 in start_thread (arg=0x7fc6e80b5700) at pthread_create.c:456
 
#15 0x00007fc6edf8bd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Query (0x7fc69c00f470): SELECT * FROM t1 FOR SYSTEM_TIME AS OF NOW()
 
Connection ID (thread ID): 9
 
Status: NOT_KILLED

10.3 debug f3f23b5c

 
mysqld: /data/src/10.3/sql/handler.cc:6364: int handler::ha_external_lock(THD*, int): Assertion `inited == NONE || table->open_by_handler' failed.
 
200711  2:50:14 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f2f2a65cf12 in __GI___assert_fail (assertion=0x55e179455818 "inited == NONE || table->open_by_handler", file=0x55e179453796 "/data/src/10.3/sql/handler.cc", line=6364, function=0x55e1794576c0 <handler::ha_external_lock(THD*, int)::__PRETTY_FUNCTION__> "int handler::ha_external_lock(THD*, int)") at assert.c:101
 
#8  0x000055e1789905ec in handler::ha_external_lock (this=0x7f2ed81811a8, thd=0x7f2ed8000af0, lock_type=2) at /data/src/10.3/sql/handler.cc:6364
 
#9  0x000055e178ab8e24 in unlock_external (thd=0x7f2ed8000af0, table=0x7f2ed8013258, count=1) at /data/src/10.3/sql/lock.cc:708
 
#10 0x000055e178ab8221 in mysql_unlock_tables (thd=0x7f2ed8000af0, sql_lock=0x7f2ed8013238, free_lock=false) at /data/src/10.3/sql/lock.cc:429
 
#11 0x000055e178ab8178 in mysql_unlock_tables (thd=0x7f2ed8000af0, sql_lock=0x7f2ed8013238) at /data/src/10.3/sql/lock.cc:415
 
#12 0x000055e1785ca473 in close_thread_tables (thd=0x7f2ed8000af0) at /data/src/10.3/sql/sql_base.cc:854
 
#13 0x000055e1785ddbb0 in close_system_tables (thd=0x7f2ed8000af0, backup=0x7f2ed818ab80) at /data/src/10.3/sql/sql_base.cc:8933
 
#14 0x000055e1785ddf3a in close_log_table (thd=0x7f2ed8000af0, backup=0x7f2ed818ab80) at /data/src/10.3/sql/sql_base.cc:9045
 
#15 0x000055e178794887 in TR_table::~TR_table (this=0x7f2f242585b0, __in_chrg=<optimized out>) at /data/src/10.3/sql/table.cc:8931
 
#16 0x000055e17887f012 in Item_func_trt_id::get_by_commit_ts (this=0x7f2ed8013a58, commit_ts=..., backwards=false) at /data/src/10.3/sql/item_vers.cc:120
 
#17 0x000055e17887f22a in Item_func_trt_id::val_int (this=0x7f2ed8013a58) at /data/src/10.3/sql/item_vers.cc:153
 
#18 0x000055e1785538d9 in Item::val_int_result (this=0x7f2ed8013a58) at /data/src/10.3/sql/item.h:1312
 
#19 0x000055e1789b8381 in Item_cache_int::cache_value (this=0x7f2ed8015f58) at /data/src/10.3/sql/item.cc:9913
 
#20 0x000055e1788722ea in Item_cache::has_value (this=0x7f2ed8015f58) at /data/src/10.3/sql/item.h:6221
 
#21 0x000055e1789b8670 in Item_cache_int::val_int (this=0x7f2ed8015f58) at /data/src/10.3/sql/item.cc:9950
 
#22 0x000055e17858c565 in Item::val_uint (this=0x7f2ed8015f58) at /data/src/10.3/sql/item.h:1072
 
#23 0x000055e17887f4d7 in Item_func_trt_trx_sees::val_int (this=0x7f2ed8013be8) at /data/src/10.3/sql/item_vers.cc:173
 
#24 0x000055e178863e93 in Type_handler_int_result::Item_val_bool (this=0x55e179d02950 <type_handler_long>, item=0x7f2ed8013be8) at /data/src/10.3/sql/sql_type.cc:3281
 
#25 0x000055e1785537a6 in Item::val_bool (this=0x7f2ed8013be8) at /data/src/10.3/sql/item.h:1215
 
#26 0x000055e1789d4d8c in Item_cond_and::val_int (this=0x7f2ed80161c8) at /data/src/10.3/sql/item_cmpfunc.cc:5072
 
#27 0x000055e1786de6d6 in evaluate_join_record (join=0x7f2ed8013288, join_tab=0x7f2ed8015648, error=0) at /data/src/10.3/sql/sql_select.cc:19826
 
#28 0x000055e1786de2d9 in sub_select (join=0x7f2ed8013288, join_tab=0x7f2ed8015648, end_of_records=false) at /data/src/10.3/sql/sql_select.cc:19731
 
#29 0x000055e1786dd7bd in do_select (join=0x7f2ed8013288, procedure=0x0) at /data/src/10.3/sql/sql_select.cc:19271
 
#30 0x000055e1786b458f in JOIN::exec_inner (this=0x7f2ed8013288) at /data/src/10.3/sql/sql_select.cc:4116
 
#31 0x000055e1786b3962 in JOIN::exec (this=0x7f2ed8013288) at /data/src/10.3/sql/sql_select.cc:3910
 
#32 0x000055e1786b4c73 in mysql_select (thd=0x7f2ed8000af0, tables=0x7f2ed8012b30, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7f2ed8013260, unit=0x7f2ed80049b8, select_lex=0x7f2ed8005140) at /data/src/10.3/sql/sql_select.cc:4315
 
#33 0x000055e1786a624a in handle_select (thd=0x7f2ed8000af0, lex=0x7f2ed80048f8, result=0x7f2ed8013260, setup_tables_done_option=0) at /data/src/10.3/sql/sql_select.cc:370
 
#34 0x000055e17866db98 in execute_sqlcom_select (thd=0x7f2ed8000af0, all_tables=0x7f2ed8012b30) at /data/src/10.3/sql/sql_parse.cc:6286
 
#35 0x000055e1786642eb in mysql_execute_command (thd=0x7f2ed8000af0) at /data/src/10.3/sql/sql_parse.cc:3812
 
#36 0x000055e178671ea3 in mysql_parse (thd=0x7f2ed8000af0, rawbuf=0x7f2ed8012818 "SELECT * FROM t1 FOR SYSTEM_TIME AS OF NOW()", length=44, parser_state=0x7f2f2425a5e0, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7810
 
#37 0x000055e17865e6ea in dispatch_command (command=COM_QUERY, thd=0x7f2ed8000af0, packet=0x7f2ed8165811 "", packet_length=44, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1848
 
#38 0x000055e17865d002 in do_command (thd=0x7f2ed8000af0) at /data/src/10.3/sql/sql_parse.cc:1393
 
#39 0x000055e1787d64d7 in do_handle_one_connection (connect=0x55e17b661290) at /data/src/10.3/sql/sql_connect.cc:1403
 
#40 0x000055e1787d6239 in handle_one_connection (arg=0x55e17b661290) at /data/src/10.3/sql/sql_connect.cc:1308
 
#41 0x000055e17918d0e8 in pfs_spawn_thread (arg=0x55e17b67c240) at /data/src/10.3/storage/perfschema/pfs.cc:1869
 
#42 0x00007f2f2c5e54a4 in start_thread (arg=0x7f2f2425b700) at pthread_create.c:456
 
#43 0x00007f2f2a719d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Query (0x7f2ed8012818): SELECT * FROM t1 FOR SYSTEM_TIME AS OF NOW()
 
Connection ID (thread ID): 9
 
Status: KILL_QUERY

Reproducible on 10.3-10.5.

 Comments   
Comment by Roel Van de Paar [ 2022-06-04 ] 

SET sql_mode=''; 
SET SESSION max_session_mem_used=45500;
 
SET system_versioning_asof='1970-01-02 00:00:00';
 
CREATE TABLE t (x INT,y INT AS (x) VIRTUAL,sys_trx_start BIGINT UNSIGNED AS ROW START INVISIBLE,sys_trx_end BIGINT UNSIGNED AS ROW END INVISIBLE,period FOR SYSTEM_TIME(sys_trx_start,sys_trx_end)) WITH SYSTEM VERSIONING;
 
INSERT INTO t (c) VALUES (1),(1),(1),(1),(1);
 
INSERT INTO t VALUES (0,0),(0,0);
 
FLUSH TABLES WITH READ LOCK;
 
UPDATE t SET C2=''WHERE C1=''AND C2='';
 
SELECT * FROM t GROUP BY c;
 
SELECT * FROM t LIMIT 2;
 
SELECT * FROM t;
 
SELECT * FROM t;

Leads to:

10.10.0 081a284712bb661349e2e3802077b12211cede3e (Debug)

 
mysqld: /test/10.10_dbg/sql/handler.cc:7050: int handler::ha_external_lock(THD*, int): Assertion `inited == NONE || table->open_by_handler' failed.

10.10.0 081a284712bb661349e2e3802077b12211cede3e (Debug)

 
Core was generated by `/test/MD310522-mariadb-10.10.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
[Current thread is 1 (Thread 0x14863c12d700 (LWP 2404300))]
 
(gdb) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x00001486622dd859 in __GI_abort () at abort.c:79
 
#2  0x00001486622dd729 in __assert_fail_base (fmt=0x148662473588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x564a93467528 "inited == NONE || table->open_by_handler", file=0x564a93465330 "/test/10.10_dbg/sql/handler.cc", line=7050, function=<optimized out>) at assert.c:92
 
#3  0x00001486622eefd6 in __GI___assert_fail (assertion=assertion@entry=0x564a93467528 "inited == NONE || table->open_by_handler", file=file@entry=0x564a93465330 "/test/10.10_dbg/sql/handler.cc", line=line@entry=7050, function=function@entry=0x564a93467490 "int handler::ha_external_lock(THD*, int)") at assert.c:101
 
#4  0x0000564a929d8018 in handler::ha_external_lock (this=0x14858402d8d0, thd=thd@entry=0x148584000db8, lock_type=lock_type@entry=2) at /test/10.10_dbg/sql/handler.cc:7050
 
#5  0x0000564a92b3c052 in handler::ha_external_unlock (thd=0x148584000db8, this=<optimized out>) at /test/10.10_dbg/sql/handler.h:3498
 
#6  unlock_external (thd=thd@entry=0x148584000db8, table=0x148584015240, count=<optimized out>) at /test/10.10_dbg/sql/lock.cc:741
 
#7  0x0000564a92b3c258 in mysql_unlock_tables (thd=0x148584000db8, sql_lock=0x148584015220, free_lock=<optimized out>) at /test/10.10_dbg/sql/lock.cc:432
 
#8  0x0000564a92b3c8de in mysql_unlock_tables (thd=thd@entry=0x148584000db8, sql_lock=<optimized out>) at /test/10.10_dbg/sql/lock.cc:415
 
#9  0x0000564a926573a0 in close_thread_tables (thd=thd@entry=0x148584000db8) at /test/10.10_dbg/sql/sql_base.cc:934
 
#10 0x0000564a92665ccf in close_log_table (thd=0x148584000db8, backup=0x1485840421d0) at /test/10.10_dbg/sql/sql_base.cc:9496
 
#11 0x0000564a92807e79 in TR_table::~TR_table (this=0x14863c12a530, __in_chrg=<optimized out>) at /test/10.10_dbg/sql/table.cc:9821
 
#12 0x0000564a92914a55 in Item_func_trt_id::get_by_commit_ts (this=this@entry=0x148584015ba0, commit_ts=@0x14863c12ac70: {year = 1970, month = 1, day = 2, hour = 0, minute = 0, second = 0, second_part = 0, neg = 0 '\000', time_type = MYSQL_TIMESTAMP_DATETIME}, backwards=<optimized out>) at /test/10.10_dbg/sql/item_vers.cc:138
 
#13 0x0000564a92914beb in Item_func_trt_id::val_int (this=0x148584015ba0) at /test/10.10_dbg/sql/item_vers.cc:170
 
#14 0x0000564a925b8ec5 in Item::val_int_result (this=<optimized out>) at /test/10.10_dbg/sql/item.h:1779
 
#15 0x0000564a929e37a9 in Item_cache_int::cache_value (this=0x1485840178b8) at /test/10.10_dbg/sql/item.cc:10107
 
#16 0x0000564a929e3846 in Item_cache::has_value (this=0x1485840178b8) at /test/10.10_dbg/sql/item.h:7080
 
#17 Item_cache_int::val_int (this=0x1485840178b8) at /test/10.10_dbg/sql/item.cc:10140
 
#18 0x0000564a929142b6 in Item::val_uint (this=<optimized out>) at /test/10.10_dbg/sql/item.h:1492
 
#19 Item_func_trt_trx_sees::val_int (this=0x148584015d08) at /test/10.10_dbg/sql/item_vers.cc:190
 
#20 0x0000564a928d871a in Type_handler_int_result::Item_val_bool (this=<optimized out>, item=<optimized out>) at /test/10.10_dbg/sql/sql_type.cc:5100
 
#21 0x0000564a925b8e32 in Item::val_bool (this=0x148584015d08) at /test/10.10_dbg/sql/item.h:1687
 
#22 0x0000564a92a130b8 in Item_cond_and::val_int (this=0x148584017af0) at /test/10.10_dbg/sql/item_cmpfunc.cc:5417
 
#23 0x0000564a92728d76 in evaluate_join_record (join=join@entry=0x1485840152f0, join_tab=join_tab@entry=0x14858408f6d0, error=error@entry=0) at /test/10.10_dbg/sql/sql_select.cc:21289
 
#24 0x0000564a9273e999 in sub_select (join=0x1485840152f0, join_tab=0x14858408f6d0, end_of_records=false) at /test/10.10_dbg/sql/sql_select.cc:21191
 
#25 0x0000564a9277227b in do_select (procedure=<optimized out>, join=0x1485840152f0) at /test/10.10_dbg/sql/sql_select.cc:20736
 
#26 JOIN::exec_inner (this=this@entry=0x1485840152f0) at /test/10.10_dbg/sql/sql_select.cc:4786
 
#27 0x0000564a92772814 in JOIN::exec (this=this@entry=0x1485840152f0) at /test/10.10_dbg/sql/sql_select.cc:4564
 
#28 0x0000564a92770598 in mysql_select (thd=thd@entry=0x148584000db8, tables=0x148584014280, fields=@0x148584013f48: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x148584014238, last = 0x148584016138, elements = 2}, <No data fields>}, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x1485840152c8, unit=0x148584004fd8, select_lex=0x148584013ca8) at /test/10.10_dbg/sql/sql_select.cc:5044
 
#29 0x0000564a92770d8e in handle_select (thd=thd@entry=0x148584000db8, lex=lex@entry=0x148584004f00, result=result@entry=0x1485840152c8, setup_tables_done_option=setup_tables_done_option@entry=0) at /test/10.10_dbg/sql/sql_select.cc:578
 
#30 0x0000564a926dcb5e in execute_sqlcom_select (thd=thd@entry=0x148584000db8, all_tables=0x148584014280) at /test/10.10_dbg/sql/sql_parse.cc:6260
 
#31 0x0000564a926e8e70 in mysql_execute_command (thd=thd@entry=0x148584000db8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.10_dbg/sql/sql_parse.cc:3944
 
#32 0x0000564a926d6e3a in mysql_parse (thd=thd@entry=0x148584000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14863c12c470) at /test/10.10_dbg/sql/sql_parse.cc:8036
 
#33 0x0000564a926e4422 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x148584000db8, packet=packet@entry=0x14858400b6d9 "", packet_length=packet_length@entry=15, blocking=blocking@entry=true) at /test/10.10_dbg/sql/sql_class.h:1364
 
#34 0x0000564a926e6b2c in do_command (thd=0x148584000db8, blocking=blocking@entry=true) at /test/10.10_dbg/sql/sql_parse.cc:1407
 
#35 0x0000564a928463c0 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x564a94fb51c8, put_in_cache=put_in_cache@entry=true) at /test/10.10_dbg/sql/sql_connect.cc:1418
 
#36 0x0000564a928468c9 in handle_one_connection (arg=0x564a94fb51c8) at /test/10.10_dbg/sql/sql_connect.cc:1312
 
#37 0x00001486627ee609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#38 0x00001486623da133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.3.36 (dbg), 10.3.36 (opt), 10.4.26 (dbg), 10.4.26 (opt), 10.5.17 (dbg), 10.5.17 (opt), 10.6.9 (dbg), 10.6.9 (opt), 10.7.5 (dbg), 10.7.5 (opt), 10.8.4 (dbg), 10.8.4 (opt), 10.9.2 (dbg), 10.9.2 (opt), 10.10.0 (dbg), 10.10.0 (opt)

Bug (or feature/syntax) confirmed not present in:
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.38 (dbg), 5.7.38 (opt), 8.0.29 (dbg), 8.0.29 (opt)

SIGSEGV|handler::update_global_table_stats|close_thread_table|close_thread_tables|close_thread_tables_for_query
 
SIGSEGV|handler::update_global_table_stats|close_thread_table|close_thread_tables|mysql_execute_command
 
inited == NONE || table->open_by_handler|SIGABRT|handler::ha_external_lock|handler::ha_external_unlock|unlock_external|mysql_unlock_tables
 
inited == NONE || table->open_by_handler|SIGABRT|handler::ha_external_lock|unlock_external|mysql_unlock_tables|mysql_unlock_tables

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