[MDEV-22104] Assertion `m_psi_batch_mode == PSI_BATCH_MODE_NONE' failed in handler::ha_close with derived_merge=off Created: 2020-04-01  Updated: 2023-12-01

Status: Confirmed
Project: MariaDB Server
Component/s: Optimizer, Server
Affects Version/s: 10.5, 10.6, 10.7, 10.8, 10.9, 10.10, 10.11
Fix Version/s: 10.5, 10.6, 10.11, 11.0, 11.1, 11.2, 11.3

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Unresolved Votes: 0
Labels: regression

Issue Links:
Relates
relates to MDEV-22882 Assertion `m_psi_batch_mode == PSI_BA... Confirmed

 Description    

--source include/have_sequence.inc
 
 
 
SET max_heap_table_size= 1048576;
 
 
 
CREATE TABLE t1 (a INT);
 
INSERT INTO t1 VALUES (1),(2);
 
CREATE TABLE t2 (a INT,  b INT, c VARCHAR(3), d VARCHAR(35));
 
INSERT INTO t2 (a) SELECT seq FROM seq_1_to_130;
 
 
 
SET optimizer_switch = 'derived_merge=off';
 
SELECT * FROM t1, ( SELECT t2a.* FROM t2 AS t2a, t2 AS t2b ) AS sq;
 
 
 
# Cleanup
 
DROP TABLE t1, t2;

10.5 244ff3e5

 
mysqld: /data/src/10.5/sql/handler.cc:2952: int handler::ha_close(): Assertion `m_psi_batch_mode == PSI_BATCH_MODE_NONE' failed.
 
200401 14:34:47 [ERROR] mysqld got signal 6 ;
 
 
 
on=0x565012138120 <handler::ha_close()::__PRETTY_FUNCTION__> "int handler::ha_close()") at assert.c:101
 
#8  0x000056501043730d in handler::ha_close (this=0x61b000041428) at /data/src/10.5/sql/handler.cc:2952
 
#9  0x000056500fda75bf in create_internal_tmp_table_from_heap (thd=0x62b000069288, table=0x62300001f9a8, start_recinfo=0x623000020e58, recinfo=0x62b00003c490, error=135, ignore_last_dupp_key_error=true, is_duplicate=0x7f364007fec0) at /data/src/10.5/sql/sql_select.cc:19846
 
#10 0x000056500ff337ed in select_unit::write_record (this=0x62b00003c418) at /data/src/10.5/sql/sql_union.cc:420
 
#11 0x000056500ff30d88 in select_unit::send_data (this=0x62b00003c418, values=...) at /data/src/10.5/sql/sql_union.cc:156
 
#12 0x000056500fdf79b3 in select_result_sink::send_data_with_check (this=0x62b00003c418, items=..., u=0x62b00003a5b0, sent=16849) at /data/src/10.5/sql/sql_class.h:5235
 
#13 0x000056500fdb524b in end_send (join=0x62b00003c500, join_tab=0x629000263a90, end_of_records=false) at /data/src/10.5/sql/sql_select.cc:21795
 
#14 0x00005650101304f4 in JOIN_CACHE::generate_full_extensions (this=0x6290002641f0, rec_ptr=0x624000064313 "\376P") at /data/src/10.5/sql/sql_join_cache.cc:2409
 
#15 0x000056501012fd92 in JOIN_CACHE::join_matching_records (this=0x6290002641f0, skip_last=false) at /data/src/10.5/sql/sql_join_cache.cc:2301
 
#16 0x000056501012e52a in JOIN_CACHE::join_records (this=0x6290002641f0, skip_last=false) at /data/src/10.5/sql/sql_join_cache.cc:2092
 
#17 0x000056500fdab315 in sub_select_cache (join=0x62b00003c500, join_tab=0x6290002636e8, end_of_records=true) at /data/src/10.5/sql/sql_select.cc:20377
 
#18 0x000056500fdab91f in sub_select (join=0x62b00003c500, join_tab=0x629000263340, end_of_records=true) at /data/src/10.5/sql/sql_select.cc:20548
 
#19 0x000056500fdaa2c3 in do_select (join=0x62b00003c500, procedure=0x0) at /data/src/10.5/sql/sql_select.cc:20139
 
#20 0x000056500fd383ba in JOIN::exec_inner (this=0x62b00003c500) at /data/src/10.5/sql/sql_select.cc:4463
 
#21 0x000056500fd35a0c in JOIN::exec (this=0x62b00003c500) at /data/src/10.5/sql/sql_select.cc:4244
 
#22 0x000056500fd39921 in mysql_select (thd=0x62b000069288, tables=0x62b000039730, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2201171004160, result=0x62b00003c418, unit=0x62b00003a5b0, select_lex=0x62b0000390d8) at /data/src/10.5/sql/sql_select.cc:4668
 
#23 0x000056500fb9397c in mysql_derived_fill (thd=0x62b000069288, lex=0x62b00006d1c8, derived=0x62b00003ae10) at /data/src/10.5/sql/sql_derived.cc:1257
 
#24 0x000056500fb8c363 in mysql_handle_single_derived (lex=0x62b00006d1c8, derived=0x62b00003ae10, phases=96) at /data/src/10.5/sql/sql_derived.cc:206
 
#25 0x000056500fd79cee in st_join_table::preread_init (this=0x629000267650) at /data/src/10.5/sql/sql_select.cc:13571
 
#26 0x000056500fdb2ac8 in join_init_read_record (tab=0x629000267650) at /data/src/10.5/sql/sql_select.cc:21541
 
#27 0x000056501013466b in JOIN_TAB_SCAN::open (this=0x6290002680b8) at /data/src/10.5/sql/sql_join_cache.cc:3357
 
#28 0x000056501012f6db in JOIN_CACHE::join_matching_records (this=0x629000267f80, skip_last=false) at /data/src/10.5/sql/sql_join_cache.cc:2260
 
#29 0x000056501012e52a in JOIN_CACHE::join_records (this=0x629000267f80, skip_last=false) at /data/src/10.5/sql/sql_join_cache.cc:2092
 
#30 0x000056500fdab315 in sub_select_cache (join=0x62b00003be98, join_tab=0x629000267650, end_of_records=true) at /data/src/10.5/sql/sql_select.cc:20377
 
#31 0x000056500fdab91f in sub_select (join=0x62b00003be98, join_tab=0x6290002672a8, end_of_records=true) at /data/src/10.5/sql/sql_select.cc:20548
 
#32 0x000056500fdaa2c3 in do_select (join=0x62b00003be98, procedure=0x0) at /data/src/10.5/sql/sql_select.cc:20139
 
#33 0x000056500fd383ba in JOIN::exec_inner (this=0x62b00003be98) at /data/src/10.5/sql/sql_select.cc:4463
 
#34 0x000056500fd35a0c in JOIN::exec (this=0x62b00003be98) at /data/src/10.5/sql/sql_select.cc:4244
 
#35 0x000056500fd39921 in mysql_select (thd=0x62b000069288, tables=0x62b0000389d8, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x62b00003be68, unit=0x62b00006d290, select_lex=0x62b0000383a8) at /data/src/10.5/sql/sql_select.cc:4668
 
#36 0x000056500fd0bc64 in handle_select (thd=0x62b000069288, lex=0x62b00006d1c8, result=0x62b00003be68, setup_tables_done_option=0) at /data/src/10.5/sql/sql_select.cc:417
 
#37 0x000056500fc7dfae in execute_sqlcom_select (thd=0x62b000069288, all_tables=0x62b0000389d8) at /data/src/10.5/sql/sql_parse.cc:6168
 
#38 0x000056500fc6c3d0 in mysql_execute_command (thd=0x62b000069288) at /data/src/10.5/sql/sql_parse.cc:3901
 
#39 0x000056500fc88ffb in mysql_parse (thd=0x62b000069288, rawbuf=0x62b0000382a8 "SELECT * FROM t1, ( SELECT t2a.* FROM t2 AS t2a, t2 AS t2b ) AS sq", length=66, parser_state=0x7f3640082a50, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7953
 
#40 0x000056500fc5edeb in dispatch_command (command=COM_QUERY, thd=0x62b000069288, packet=0x629000249289 "", packet_length=66, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1839
 
#41 0x000056500fc5b820 in do_command (thd=0x62b000069288) at /data/src/10.5/sql/sql_parse.cc:1358
 
#42 0x00005650100788ab in do_handle_one_connection (connect=0x61100001fd88, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1422
 
#43 0x0000565010078146 in handle_one_connection (arg=0x61100001fc48) at /data/src/10.5/sql/sql_connect.cc:1319
 
#44 0x0000565010d1601a in pfs_spawn_thread (arg=0x616000009108) at /data/src/10.5/storage/perfschema/pfs.cc:2201
 
#45 0x00007f3649269fa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
 
#46 0x00007f3648ab84cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Execution plan with derived_merge=on as in the default optimizer_switch (no crash)

 
# id	select_type	table	type	possible_keys	key	key_len	ref	rows	filtered	Extra
 
# 1	SIMPLE	t1	ALL	NULL	NULL	NULL	NULL	2	100.00	
# 1	SIMPLE	t2a	ALL	NULL	NULL	NULL	NULL	130	100.00	Using join buffer (flat, BNL join)
 
# 1	SIMPLE	t2b	ALL	NULL	NULL	NULL	NULL	130	100.00	Using join buffer (incremental, BNL join)
 
# Warnings:
 
# Note	1003	select `test`.`t1`.`a` AS `a`,`test`.`t2a`.`a` AS `a`,`test`.`t2a`.`b` AS `b`,`test`.`t2a`.`c` AS `c`,`test`.`t2a`.`d` AS `d` from `test`.`t1` join `test`.`t2` `t2a` join `test`.`t2` `t2b`

Execution plan with derived_merge=off (crash)

 
# EXPLAIN EXTENDED SELECT * FROM t1, ( SELECT t2a.* FROM t2 AS t2a, t2 AS t2b ) AS sq;
 
# id	select_type	table	type	possible_keys	key	key_len	ref	rows	filtered	Extra
 
# 1	PRIMARY	t1	ALL	NULL	NULL	NULL	NULL	2	100.00	
# 1	PRIMARY	<derived2>	ALL	NULL	NULL	NULL	NULL	16900	100.00	Using join buffer (flat, BNL join)
 
# 2	DERIVED	t2a	ALL	NULL	NULL	NULL	NULL	130	100.00	
# 2	DERIVED	t2b	ALL	NULL	NULL	NULL	NULL	130	100.00	Using join buffer (flat, BNL join)
 
# Warnings:
 
# Note	1003	/* select#1 */ select `test`.`t1`.`a` AS `a`,`sq`.`a` AS `a`,`sq`.`b` AS `b`,`sq`.`c` AS `c`,`sq`.`d` AS `d` from `test`.`t1` join (/* select#2 */ select `test`.`t2a`.`a` AS `a`,`test`.`t2a`.`b` AS `b`,`test`.`t2a`.`c` AS `c`,`test`.`t2a`.`d` AS `d` from `test`.`t2` `t2a` join `test`.`t2` `t2b`) `sq`

Reproducible with at least InnoDB, MyISAM, Aria.
No obvious problem on a non-debug build.
Not reproducible on 10.4.

The failure started happening after the 5.7 performance schema merge. The first failing revision that I could compile was

commit 7af733a5a2cb7f79ffb5ff0129cad6db6f3cc359
 
Author: Sergei Golubchik
 
Date:   Sat Feb 15 18:25:57 2020 +0100
 
 
 
    perfschema compilation, test and misc fixes



 Comments   
Comment by Elena Stepanova [ 2020-05-10 ]

Here is a test case which doesn't need a non-default optimizer_switch:

--source include/have_sequence.inc
 
 
 
SET max_heap_table_size= 1048576;
 
 
 
CREATE  TABLE t1 (a VARCHAR(4000), b INT);
 
INSERT INTO t1 SELECT '', seq FROM seq_1_to_258;
 
 
 
CREATE  TABLE t2 (c INT);
 
INSERT INTO t2 VALUES (1),(2);
 
 
 
CREATE ALGORITHM=TEMPTABLE VIEW v1 AS SELECT * FROM t1;
 
SELECT c FROM v1, t2 WHERE c = 1;
 
 
 
# Cleanup
 
DROP VIEW v1;
 
DROP TABLE t1, t2;

10.5 cfe5ee90

 
mariadbd: /data/src/10.5/sql/handler.cc:2967: int handler::ha_close(): Assertion `m_psi_batch_mode == PSI_BATCH_MODE_NONE' failed.
 
200510 17:54:42 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007ff922aeaf12 in __GI___assert_fail (assertion=0x55faba5a3e30 "m_psi_batch_mode == PSI_BATCH_MODE_NONE", file=0x55faba5a2bde "/data/src/10.5/sql/handler.cc", line=2967, function=0x55faba5a6170 <handler::ha_close()::__PRETTY_FUNCTION__> "int handler::ha_close()") at assert.c:101
 
#8  0x000055fab99799dc in handler::ha_close (this=0x7ff90c21aff0) at /data/src/10.5/sql/handler.cc:2967
 
#9  0x000055fab969e07d in create_internal_tmp_table_from_heap (thd=0x7ff90c000b18, table=0x7ff90c219430, start_recinfo=0x7ff90c21a8a8, recinfo=0x7ff90c019538, error=135, ignore_last_dupp_key_error=true, is_duplicate=0x7ff91d686d7f) at /data/src/10.5/sql/sql_select.cc:19858
 
#10 0x000055fab9735857 in select_unit::write_record (this=0x7ff90c0194c0) at /data/src/10.5/sql/sql_union.cc:420
 
#11 0x000055fab9734a59 in select_unit::send_data (this=0x7ff90c0194c0, values=...) at /data/src/10.5/sql/sql_union.cc:156
 
#12 0x000055fab96bbf27 in select_result_sink::send_data_with_check (this=0x7ff90c0194c0, items=..., u=0x7ff90c015cd0, sent=257) at /data/src/10.5/sql/sql_class.h:5237
 
#13 0x000055fab96a2ec2 in end_send (join=0x7ff90c215938, join_tab=0x7ff90c216f98, end_of_records=false) at /data/src/10.5/sql/sql_select.cc:21807
 
#14 0x000055fab96a0556 in evaluate_join_record (join=0x7ff90c215938, join_tab=0x7ff90c216bf0, error=0) at /data/src/10.5/sql/sql_select.cc:20838
 
#15 0x000055fab969ffd8 in sub_select (join=0x7ff90c215938, join_tab=0x7ff90c216bf0, end_of_records=false) at /data/src/10.5/sql/sql_select.cc:20654
 
#16 0x000055fab969f276 in do_select (join=0x7ff90c215938, procedure=0x0) at /data/src/10.5/sql/sql_select.cc:20149
 
#17 0x000055fab9673009 in JOIN::exec_inner (this=0x7ff90c215938) at /data/src/10.5/sql/sql_select.cc:4464
 
#18 0x000055fab9672135 in JOIN::exec (this=0x7ff90c215938) at /data/src/10.5/sql/sql_select.cc:4245
 
#19 0x000055fab9673866 in mysql_select (thd=0x7ff90c000b18, tables=0x7ff90c017fd0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2201171004160, result=0x7ff90c0194c0, unit=0x7ff90c015cd0, select_lex=0x7ff90c0177c8) at /data/src/10.5/sql/sql_select.cc:4669
 
#20 0x000055fab95c4e24 in mysql_derived_fill (thd=0x7ff90c000b18, lex=0x7ff90c004a60, derived=0x7ff90c013ff8) at /data/src/10.5/sql/sql_derived.cc:1267
 
#21 0x000055fab95c1e0c in mysql_handle_single_derived (lex=0x7ff90c004a60, derived=0x7ff90c013ff8, phases=96) at /data/src/10.5/sql/sql_derived.cc:206
 
#22 0x000055fab968cc97 in st_join_table::preread_init (this=0x7ff90c21f018) at /data/src/10.5/sql/sql_select.cc:13583
 
#23 0x000055fab96a2173 in join_init_read_record (tab=0x7ff90c21f018) at /data/src/10.5/sql/sql_select.cc:21553
 
#24 0x000055fab9811a70 in JOIN_TAB_SCAN::open (this=0x7ff90c21fa68) at /data/src/10.5/sql/sql_join_cache.cc:3357
 
#25 0x000055fab980fe66 in JOIN_CACHE::join_matching_records (this=0x7ff90c21f938, skip_last=false) at /data/src/10.5/sql/sql_join_cache.cc:2260
 
#26 0x000055fab980f935 in JOIN_CACHE::join_records (this=0x7ff90c21f938, skip_last=false) at /data/src/10.5/sql/sql_join_cache.cc:2092
 
#27 0x000055fab969f9a9 in sub_select_cache (join=0x7ff90c2153c0, join_tab=0x7ff90c21f018, end_of_records=true) at /data/src/10.5/sql/sql_select.cc:20389
 
#28 0x000055fab969fbb4 in sub_select (join=0x7ff90c2153c0, join_tab=0x7ff90c21ec70, end_of_records=true) at /data/src/10.5/sql/sql_select.cc:20560
 
#29 0x000055fab969f2dc in do_select (join=0x7ff90c2153c0, procedure=0x0) at /data/src/10.5/sql/sql_select.cc:20151
 
#30 0x000055fab9673009 in JOIN::exec_inner (this=0x7ff90c2153c0) at /data/src/10.5/sql/sql_select.cc:4464
 
#31 0x000055fab9672135 in JOIN::exec (this=0x7ff90c2153c0) at /data/src/10.5/sql/sql_select.cc:4245
 
#32 0x000055fab9673866 in mysql_select (thd=0x7ff90c000b18, tables=0x7ff90c013ff8, fields=..., conds=0x7ff90c014fe8, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7ff90c019498, unit=0x7ff90c004b28, select_lex=0x7ff90c0139f8) at /data/src/10.5/sql/sql_select.cc:4669
 
#33 0x000055fab966337c in handle_select (thd=0x7ff90c000b18, lex=0x7ff90c004a60, result=0x7ff90c019498, setup_tables_done_option=0) at /data/src/10.5/sql/sql_select.cc:429
 
#34 0x000055fab96289b2 in execute_sqlcom_select (thd=0x7ff90c000b18, all_tables=0x7ff90c013ff8) at /data/src/10.5/sql/sql_parse.cc:6172
 
#35 0x000055fab961fcf8 in mysql_execute_command (thd=0x7ff90c000b18) at /data/src/10.5/sql/sql_parse.cc:3901
 
#36 0x000055fab962d860 in mysql_parse (thd=0x7ff90c000b18, rawbuf=0x7ff90c013950 "SELECT c FROM v1, t2 WHERE c = 1", length=32, parser_state=0x7ff91d688520, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7957
 
#37 0x000055fab9619b68 in dispatch_command (command=COM_QUERY, thd=0x7ff90c000b18, packet=0x7ff90c1b0409 "", packet_length=32, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1840
 
#38 0x000055fab96182fa in do_command (thd=0x7ff90c000b18) at /data/src/10.5/sql/sql_parse.cc:1359
 
#39 0x000055fab97bb883 in do_handle_one_connection (connect=0x55fabe079bd8, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1411
 
#40 0x000055fab97bb5eb in handle_one_connection (arg=0x55fabe079bd8) at /data/src/10.5/sql/sql_connect.cc:1313
 
#41 0x000055fab9cf0ea0 in pfs_spawn_thread (arg=0x55fabe0055e8) at /data/src/10.5/storage/perfschema/pfs.cc:2201
 
#42 0x00007ff924a734a4 in start_thread (arg=0x7ff91d689700) at pthread_create.c:456
 
#43 0x00007ff922ba7d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Reproducible with at least MyISAM and InnoDB.

Comment by Roel Van de Paar [ 2020-06-13 ]

Possibly connected with MDEV-22882 (ref 3rd testcase), though there seems to be more then one issue at work (re UNION).

Comment by Roel Van de Paar [ 2020-06-13 ]

Both testcases in this report somehow do not crash from me, either on 10.5.4 (dbg) revision 6877ef9a7c9c7ee55d67e4baaf4e8f7b874c9f89 or 07d1c8567cbfe94398a9857c47fb9919cad42651. This at least in part matches with being unable to reproduce the 3 testcases of MDEV-22882 against 07d1c8567cbfe94398a9857c47fb9919cad42651 though not against 6877ef9a7c9c7ee55d67e4baaf4e8f7b874c9f89.

Comment by Elena Stepanova [ 2020-06-13 ]

Thanks Roel. Both test cases still fail fine on the latest 10.5, but they assumed running in MTR, which isn't very accurate. I've now added explicit SET max_heap_table_size= 1048576 (MTR's default) to both of them.

Comment by Roel Van de Paar [ 2020-06-17 ]

Yes, that did it. Thank you

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