[MDEV-17839] Crash (pure virtual method called) in or around handler::ha_external_lock for simple SELECT with join Created: 2018-11-26  Updated: 2020-08-25  Resolved: 2019-01-18

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.0, 10.1, 10.1.29, 10.2
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Valerii Kravchuk Assignee: Varun Gupta (Inactive)
Resolution: Duplicate Votes: 2
Labels: None

Issue Links:
Duplicate
duplicates MDEV-17597 [Draft] pure virtual method called in... Closed
is duplicated by MDEV-14440 Server crash in in handler::ha_extern... Closed
is duplicated by MDEV-17982 Restarting MariaDB service Closed
Relates
relates to MDEV-17877 Hitting Bug while adding new partitio... Closed
relates to MDEV-14440 Server crash in in handler::ha_extern... Closed

 Description   

MariaDB 10.1.29 crashed as follows:

(gdb) bt
 
#0 0x00007ffff5c6e207 in raise () from /lib64/libc.so.6
 
#1 0x00007ffff5c6f8f8 in abort () from /lib64/libc.so.6
 
#2 0x00007ffff5cb0cc7 in __libc_message () from /lib64/libc.so.6
 
#3 0x00007ffff5d50677 in __fortify_fail () from /lib64/libc.so.6
 
#4 0x00007ffff5d4e7f2 in __chk_fail () from /lib64/libc.so.6
 
#5 0x00007ffff5d505d7 in __fdelt_warn () from /lib64/libc.so.6
 
#6 0x00005555560051b8 in my_addr_resolve (ptr=0x555555ff165e <my_print_stacktrace+46>, loc=loc@entry=0x7feb404a4830) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/mysys/my_addr_resolve.c:162
 
#7 0x0000555555ff17f2 in print_with_addr_resolve (n=<optimized out>, addrs=0x7feb404a4850) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/mysys/stacktrace.c:253
 
#8 my_print_stacktrace (stack_bottom=<optimized out>, thread_stack=295936) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/mysys/stacktrace.c:271
 
#9 0x0000555555b15015 in handle_fatal_signal (sig=6) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/signal_handler.cc:166
 
#10 <signal handler called>
 
#11 0x00007ffff5c6e207 in raise () from /lib64/libc.so.6
 
#12 0x00007ffff5c6f8f8 in abort () from /lib64/libc.so.6
 
#13 0x00007ffff63677d5 in __gnu_cxx::__verbose_terminate_handler() () from /lib64/libstdc++.so.6
 
#14 0x00007ffff6365746 in ?? () from /lib64/libstdc++.so.6
 
#15 0x00007ffff6365773 in std::terminate() () from /lib64/libstdc++.so.6
 
#16 0x00007ffff63662df in __cxa_pure_virtual () from /lib64/libstdc++.so.6
 
#17 0x0000555555b1f81b in handler::ha_external_lock (this=0x7fe48da10820, thd=thd@entry=0x7fe492821008, lock_type=lock_type@entry=2) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/handler.cc:5891
 
#18 0x0000555555bdfbe5 in unlock_external (count=<optimized out>, table=0x7fe44cae3f98, thd=0x7fe492821008) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/lock.cc:689
 
#19 mysql_unlock_read_tables (thd=0x7fe492821008, sql_lock=0x7fe44cae3f60) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/lock.cc:450
 
#20 0x00005555559d297b in JOIN::join_free (this=this@entry=0x7fe44cae3fc8) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_select.cc:11990
 
#21 0x00005555559d2c24 in do_select (join=join@entry=0x7fe44cae3fc8, fields=fields@entry=0x7fe492825160, table=table@entry=0x0, procedure=0x0) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_select.cc:18103
 
#22 0x00005555559e565c in JOIN::exec_inner (this=this@entry=0x7fe44cae3fc8) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_select.cc:3225
 
#23 0x00005555559e7664 in JOIN::exec (this=this@entry=0x7fe44cae3fc8) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_select.cc:2512
 
#24 0x00005555559e3ce2 in mysql_select (thd=thd@entry=0x7fe492821008, rref_pointer_array=rref_pointer_array@entry=0x7fe4928252f0, tables=<optimized out>, wild_num=<optimized out>, fields=..., conds=<optimized out>, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2148272640,
 
result=result@entry=0x7fe44cae3fa8, unit=unit@entry=0x7fe492824948, select_lex=select_lex@entry=0x7fe492825048) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_select.cc:3449
 
#25 0x00005555559e47e5 in handle_select (thd=thd@entry=0x7fe492821008, lex=lex@entry=0x7fe492824880, result=result@entry=0x7fe44cae3fa8, setup_tables_done_option=setup_tables_done_option@entry=0) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_select.cc:384
 
#26 0x00005555558ca44f in execute_sqlcom_select (thd=thd@entry=0x7fe492821008, all_tables=0x7fe44cae2450) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_parse.cc:5923
 
#27 0x000055555598f10e in mysql_execute_command (thd=thd@entry=0x7fe492821008) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_parse.cc:2975
 
#28 0x0000555555991cc2 in mysql_parse (thd=0x7fe492821008, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_parse.cc:7344
 
#29 0x000055555599562a in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fe492821008, packet=packet@entry=0x7fe478deb009 "", packet_length=packet_length@entry=288) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_parse.cc:1477
 
#30 0x0000555555995f86 in do_command (thd=0x7fe492821008) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_parse.cc:1106
 
#31 0x0000555555a61dfa in do_handle_one_connection (thd_arg=thd_arg@entry=0x7fe4904c7008) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_connect.cc:1349
 
#32 0x0000555555a61fa0 in handle_one_connection (arg=arg@entry=0x7fe4904c7008) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/sql/sql_connect.cc:1261
 
#33 0x0000555555ca249d in pfs_spawn_thread (arg=0x7fe4675b0c08) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.1.29/storage/perfschema/pfs.cc:1861
 
#34 0x00007ffff7bc5dd5 in start_thread () from /lib64/libpthread.so.0
 
#35 0x00007ffff5d36b3d in clone () from /lib64/libc.so.6

Crashing query was simple enough SELECT joining two (small) InnoDB tables, like this:

select
 
t1.*
 
from
 
t1, t
 
where
 
t.id1 = 577
 
and t1.c1 = 'something'
 
and t.ts = t1.somets
 
and t.id1 = t1.id1;

Running the query again after restart does not lead to crashes. There is nothing in the error log for days before the crash. EXPLAIN output after restart is like this:

*************************** 1. row ***************************
 
id: 1
 
select_type: SIMPLE
 
table: t
 
type: ref
 
possible_keys: unq,id1,id2
 
key: id2
 
key_len: 4
 
ref: const
 
rows: 3984
 
Extra: Using index
 
*************************** 2. row ***************************
 
id: 1
 
select_type: SIMPLE
 
table: t1
 
type: ref
 
possible_keys: c1,id1,somets
 
key: somets
 
key_len: 9
 
ref: db.t.ts
 
rows: 1
 
Extra: Using index condition; Using where
 
2 rows in set (0.01 sec)

May be related/similar to https://jira.mariadb.org/browse/MDEV-17597, but no downgrade happened.

 Comments   
Comment by Elena Stepanova [ 2018-11-27 ]

MDEV-17597 can still be related, I don't think downgrade played an important role there (it was a minor downgrade from 10.2.18+ to 10.2.18). It just happened to happen during the downgrade test. Since the tests are run regularly and it was a one-time occurrence, it might be a very rare incident, in which case chances for reproducing it quickly are very slim.

Comment by Elena Stepanova [ 2018-11-28 ]

It turns out that the test case from MDEV-14440, when run on a non-debug build, can produce a very similar crash, only for a partitioned table.

Comment by Elena Stepanova [ 2018-11-28 ]

10.1.29 release bintar

 
Version: '10.1.29-MariaDB'  socket: '/data/releases.old/10.1.29/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  MariaDB Server
 
pure virtual method called
 
terminate called without an active exception
 
181129 19:05:35 [ERROR] mysqld got signal 6 ;
 
 
 
#3  0x00007fcc63549fcf in raise () from /lib/x86_64-linux-gnu/libc.so.6
 
#4  0x00007fcc6354b3fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#5  0x00007fcc63c4a0ad in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
 
#6  0x00007fcc63c48066 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
 
#7  0x00007fcc63c480b1 in std::terminate() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
 
#8  0x00007fcc63c48b8f in __cxa_pure_virtual () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
 
#9  0x000055a9855f54db in handler::ha_external_lock (this=0x7fcc4e053020, thd=thd@entry=0x7fcc59a97008, lock_type=lock_type@entry=2) at /home/buildbot/buildbot/build/sql/handler.cc:5891
 
#10 0x000055a9856a618b in unlock_external (thd=thd@entry=0x7fcc59a97008, table=0x7fcc4d983f18, count=<optimized out>) at /home/buildbot/buildbot/build/sql/lock.cc:689
 
#11 0x000055a9856a642c in mysql_unlock_tables (thd=0x7fcc59a97008, sql_lock=0x7fcc4d983ef0, free_lock=<optimized out>) at /home/buildbot/buildbot/build/sql/lock.cc:399
 
#12 0x000055a9856a6498 in mysql_unlock_tables (thd=<optimized out>, sql_lock=<optimized out>) at /home/buildbot/buildbot/build/sql/lock.cc:388
 
#13 0x000055a98542eec7 in close_thread_tables (thd=thd@entry=0x7fcc59a97008) at /home/buildbot/buildbot/build/sql/sql_base.cc:1028
 
#14 0x000055a985472f12 in mysql_execute_command (thd=thd@entry=0x7fcc59a97008) at /home/buildbot/buildbot/build/sql/sql_parse.cc:5753
 
#15 0x000055a98547b8a5 in mysql_parse (thd=0x7fcc59a97008, rawbuf=<optimized out>, length=<optimized out>, parser_state=0x7fcc64af9610) at /home/buildbot/buildbot/build/sql/sql_parse.cc:7344
 
#16 0x000055a98547e39e in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fcc59a97008, packet=0x7fcc4d983020 "UPDATE t1 SET i = pk + 1 WHERE pk = 1", packet_length=packet_length@entry=37) at /home/buildbot/buildbot/build/sql/sql_parse.cc:1477
 
#17 0x000055a98547e90e in do_command (thd=0x7fcc59a97008) at /home/buildbot/buildbot/build/sql/sql_parse.cc:1106
 
#18 0x000055a98553f21f in do_handle_one_connection (thd_arg=thd_arg@entry=0x7fcc59a97008) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1349
 
#19 0x000055a98553f357 in handle_one_connection (arg=arg@entry=0x7fcc59a97008) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1261
 
#20 0x000055a98575b9fd in pfs_spawn_thread (arg=0x7fcc6283f808) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#21 0x00007fcc63f42494 in start_thread (arg=0x7fcc64afab00) at pthread_create.c:333
 
#22 0x00007fcc635ff93f in clone () from /lib/x86_64-linux-gnu/libc.so.6


--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (pk SERIAL, i INT, PRIMARY KEY(pk)) ENGINE=InnoDB;
 
INSERT INTO t1 () VALUES
 
(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),
 
(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),
 
(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),
 
(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),
 
(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),
 
(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),
 
(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),
 
(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),
 
(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),(),
 
(),();
 
 
 
CREATE TABLE t2 (pk INT PRIMARY KEY) ENGINE=InnoDB;
 
 
 
START TRANSACTION;
 
SELECT pk FROM t2;
 
 
 
--connect (con1,localhost,root,,test)
 
INSERT INTO t1 () VALUES (),(),(),();
 
 
 
--connect (con2,localhost,root,,test)
 
ALTER TABLE t1 FORCE;
 
INSERT INTO t1 () VALUES ();
 
 
 
--connection default
 
UPDATE t1 SET i = pk + 1 WHERE pk = 1;
 
 
 
# Cleanup
 
--disconnect con1
 
--disconnect con2
 
--connection default
 
DROP TABLE t1, t2;

The "pure virtual method called" error above seems to be specific to our release builds (not just RelWIthDebInfo from source, but actual release builds). On debug builds I get failures very similar to MDEV-14440:

10.1 328d7779bc

 
mysqld: /data/src/10.1/sql/handler.h:2810: int handler::ha_rnd_end(): Assertion `inited==RND' failed.
 
181129 19:11:16 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f279e3d7ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x000055d1a748f338 in handler::ha_rnd_end (this=0x7f2788866088) at /data/src/10.1/sql/handler.h:2810
 
#9  0x000055d1a78612c7 in QUICK_ROR_INTERSECT_SELECT::~QUICK_ROR_INTERSECT_SELECT (this=0x7f278801f580, __in_chrg=<optimized out>) at /data/src/10.1/sql/opt_range.cc:1698
 
#10 0x000055d1a7861326 in QUICK_ROR_INTERSECT_SELECT::~QUICK_ROR_INTERSECT_SELECT (this=0x7f278801f580, __in_chrg=<optimized out>) at /data/src/10.1/sql/opt_range.cc:1700
 
#11 0x000055d1a785fcdd in SQL_SELECT::cleanup (this=0x7f2788044070) at /data/src/10.1/sql/opt_range.cc:1209
 
#12 0x000055d1a785fd64 in SQL_SELECT::~SQL_SELECT (this=0x7f2788044070, __in_chrg=<optimized out>) at /data/src/10.1/sql/opt_range.cc:1223
 
#13 0x000055d1a75df804 in mysql_update (thd=0x7f2794bc7070, table_list=0x7f2788043180, fields=..., values=..., conds=0x7f2788043cb0, order_num=0, order=0x0, limit=18446744073709551615, handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7f27a022fcc0, updated_return=0x7f27a022fd50) at /data/src/10.1/sql/sql_update.cc:1057
 
#14 0x000055d1a7502b9e in mysql_execute_command (thd=0x7f2794bc7070) at /data/src/10.1/sql/sql_parse.cc:3789
 
#15 0x000055d1a750e075 in mysql_parse (thd=0x7f2794bc7070, rawbuf=0x7f2788043088 "UPDATE t1 SET i = pk + 1 WHERE pk = 1", length=37, parser_state=0x7f27a02305e0) at /data/src/10.1/sql/sql_parse.cc:7467
 
#16 0x000055d1a74fc8c6 in dispatch_command (command=COM_QUERY, thd=0x7f2794bc7070, packet=0x7f2796ac3071 "UPDATE t1 SET i = pk + 1 WHERE pk = 1", packet_length=37) at /data/src/10.1/sql/sql_parse.cc:1495
 
#17 0x000055d1a74fb64b in do_command (thd=0x7f2794bc7070) at /data/src/10.1/sql/sql_parse.cc:1124
 
#18 0x000055d1a76361aa in do_handle_one_connection (thd_arg=0x7f2794bc7070) at /data/src/10.1/sql/sql_connect.cc:1330
 
#19 0x000055d1a7635f0e in handle_one_connection (arg=0x7f2794bc7070) at /data/src/10.1/sql/sql_connect.cc:1242
 
#20 0x000055d1a79f4238 in pfs_spawn_thread (arg=0x7f2798ff2670) at /data/src/10.1/storage/perfschema/pfs.cc:1861
 
#21 0x00007f279fec0494 in start_thread (arg=0x7f27a0231b00) at pthread_create.c:333
 
#22 0x00007f279e49493f in clone () from /lib/x86_64-linux-gnu/libc.so.6

And on source non-debug builds, I get either the error ER_TABLE_DEF_CHANGED, or SIGSEGV similar to the one in MDEV-14440 (only without partitioning).

With all likelihood, the fix for MDEV-14440 will fix this issue as well, but i will assign it to varun to make sure of that.

Comment by Elena Stepanova [ 2018-11-29 ]

I removed 10.3 from the affected versions, because I couldn't make current 10.3 produce the "crashing" plan with this test case.

The "crashing" plan on the previous versions is this:

EXPLAIN UPDATE t1  SET i = pk + 1 WHERE pk = 1;
 
id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
 
1	SIMPLE	t1	index_merge	PRIMARY,pk	pk,PRIMARY	8,8	NULL	1	Using intersect(pk,PRIMARY); Using where
 
UPDATE t1 SET i = pk + 1 WHERE pk = 1;

and "non-crashing" plan is this:

id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
 
1	SIMPLE	t1	range	PRIMARY,pk	PRIMARY	8	NULL	1	Using where
 
UPDATE t1 FORCE INDEX (pk,PRIMARY) SET i = pk + 1 WHERE pk = 1;

Comment by Arnaud Adant [ 2019-01-17 ]

As this bug is not fixed yet, what is the workaround ?
Looks like disabling index merge intersect prevents the crash from happening :

set session optimizer_switch =  "index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=off,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=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=off"

Comment by Varun Gupta (Inactive) [ 2019-01-18 ]

This is fixed by MDEV-14440

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