[MDEV-22910] SIGSEGV in Opt_trace_context::is_started & SIGSEGV in Json_writer::add_table_name (on optimized builds) Created: 2020-06-16  Updated: 2020-07-01  Resolved: 2020-07-01

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.5.4, 10.4.14
Fix Version/s: 10.4.14, 10.5.5

Type: Bug Priority: Critical
Reporter: Roel Van de Paar Assignee: Varun Gupta (Inactive)
Resolution: Fixed Votes: 0
Labels: not-10.1, not-10.2, not-10.3, optimizer, regression


 Description   

# Keep testcase repeating until mysqld crashes (one time often if not always enough on debug, optimized may take 2-x attempts)
USE test;
SET SQL_MODE='';
SET SESSION enforce_storage_engine=MEMORY;
SET SESSION optimizer_trace='enabled=on';
CREATE TABLE t1( a INT, b INT, KEY( a ) ) ;
SELECT MAX(a), SUM(MAX(a)) OVER () FROM t1 WHERE a > 10;
SELECT * FROM information_schema.session_variables WHERE variable_name='innodb_ft_min_token_size';
UPDATE t1 SET b=REPEAT(LEFT(b,1),200) WHERE a=1;

Leads to:

10.5.4 4080e3acefd7e58d88c2f3539fb6a0fb359cf057

Core was generated by `/test/MD150620-mariadb-10.5.4-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
[Current thread is 1 (Thread 0x14e11810c700 (LWP 1655068))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x000055565b1b74c6 in my_write_core (sig=sig@entry=11) at /test/10.5_dbg/mysys/stacktrace.c:518
#2  0x000055565a959d60 in handle_fatal_signal (sig=11) at /test/10.5_dbg/sql/signal_handler.cc:330
#3  <signal handler called>
#4  Opt_trace_context::is_started (this=<error reading variable: Cannot access memory at address 0x8f8f8f8f8f8f910f>) at /test/10.5_dbg/sql/opt_trace_context.h:108
#5  THD::trace_started (this=<error reading variable: Cannot access memory at address 0x8f8f8f8f8f8f910f>) at /test/10.5_dbg/sql/sql_class.h:3407
#6  Json_writer::add_table_name (this=0x14e0ff471600, tab=tab@entry=0x14e0ff478710) at /test/10.5_dbg/sql/opt_trace.cc:561
#7  0x000055565aaf562f in Json_value_helper::add_table_name (tab=0x14e0ff478710, this=0x14e118108438) at /test/10.5_dbg/sql/my_json_writer.h:300
#8  Json_writer_object::add_table_name (tab=0x14e0ff478710, this=0x14e118108430) at /test/10.5_dbg/sql/my_json_writer.h:474
#9  SQL_SELECT::test_quick_select (this=this@entry=0x14e0ff4754f0, thd=thd@entry=0x14e0ff415088, keys_to_use={static BITS_PER_ELEMENT = 64, static ARRAY_ELEMENTS = 1, static ALL_BITS_SET = 18446744073709551615, buffer = {18446744073709551615}}, prev_tables=prev_tables@entry=0, limit=limit@entry=18446744073709551615, force_quick_range=force_quick_range@entry=false, ordered_output=false, remove_false_parts_of_where=false, only_single_index_range_scan=false) at /test/10.5_dbg/sql/opt_range.cc:2695
#10 0x000055565a7a59ad in SQL_SELECT::check_quick (limit=18446744073709551615, force_quick_range=<optimized out>, thd=0x14e0ff415088, this=0x14e0ff4754f0) at /test/10.5_dbg/sql/opt_range.h:1655
#11 mysql_update (thd=thd@entry=0x14e0ff415088, table_list=<optimized out>, fields=@0x14e0ff4199f0: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14e0ff474e30, last = 0x14e0ff474e30, elements = 1}, <No data fields>}, values=@0x14e0ff419f68: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14e0ff474e40, last = 0x14e0ff474e40, elements = 1}, <No data fields>}, conds=<optimized out>, order_num=<optimized out>, order=0x0, limit=18446744073709551615, ignore=false, found_return=0x14e11810aca0, updated_return=0x14e11810ad70) at /test/10.5_dbg/sql/sql_update.cc:555
#12 0x000055565a6b062c in mysql_execute_command (thd=thd@entry=0x14e0ff415088) at /test/10.5_dbg/sql/sql_parse.cc:4401
#13 0x000055565a6bc15c in mysql_parse (thd=thd@entry=0x14e0ff415088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14e11810b350, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7993
#14 0x000055565a6a8c60 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14e0ff415088, packet=packet@entry=0x14e0ff467089 "UPDATE t1 SET b=REPEAT(LEFT(b,1),200) WHERE a=1", packet_length=packet_length@entry=47, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1874
#15 0x000055565a6a743a in do_command (thd=0x14e0ff415088) at /test/10.5_dbg/sql/sql_parse.cc:1355
#16 0x000055565a802c47 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x14e10197a108, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1411
#17 0x000055565a803363 in handle_one_connection (arg=arg@entry=0x14e10197a108) at /test/10.5_dbg/sql/sql_connect.cc:1313
#18 0x000055565ac64902 in pfs_spawn_thread (arg=0x14e11f046c88) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
#19 0x000014e1211486db in start_thread (arg=0x14e11810c700) at pthread_create.c:463
#20 0x000014e12054688f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.14 (dbg), 10.4.14 (opt), 10.5.4 (dbg), 10.5.4 (opt)

Bug confirmed not present in:
MariaDB: 10.1.46 (dbg), 10.1.46 (opt), 10.2.33 (dbg), 10.2.33 (opt), 10.3.24 (dbg), 10.3.24 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)



 Comments   
Comment by Roel Van de Paar [ 2020-06-16 ]

The bug seemingly causes sporadic-location delayed crashes in what looks to be completely unrelated code. [UPDATED: Ref next comment]

Example: using the testcase above, executed twice, against 10.5.4 optimized, crashes (SIGSEGV) in JSON code:

10.5.4 4080e3acefd7e58d88c2f3539fb6a0fb359cf057

Core was generated by `/test/MD150620-mariadb-10.5.4-linux-x86_64-opt/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
[Current thread is 1 (Thread 0x147dab73b700 (LWP 1826601))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x0000556af9ae80b7 in my_write_core (sig=sig@entry=11) at /test/10.5_opt/mysys/stacktrace.c:518
#2  0x0000556af94b1e4a in handle_fatal_signal (sig=11) at /test/10.5_opt/sql/signal_handler.cc:330
#3  <signal handler called>
#4  0x0000556af94320fb in Json_writer::add_table_name (this=0x147d878953c0, 
    tab=tab@entry=0x147d8784b608) at /test/10.5_opt/sql/opt_trace.cc:579
#5  0x0000556af95d900c in Json_value_helper::add_table_name (tab=0x147d8784b608, this=0x147dab737848)
    at /test/10.5_opt/sql/my_json_writer.h:300
#6  Json_writer_object::add_table_name (tab=0x147d8784b608, this=0x147dab737840)
    at /test/10.5_opt/sql/my_json_writer.h:474
#7  SQL_SELECT::test_quick_select (this=this@entry=0x147d87848480, thd=thd@entry=0x147d87812018, 
    keys_to_use=keys_to_use@entry=..., prev_tables=prev_tables@entry=0, 
    limit=limit@entry=18446744073709551615, force_quick_range=false, ordered_output=false, 
    remove_false_parts_of_where=false, only_single_index_range_scan=false)
    at /test/10.5_opt/sql/opt_range.cc:2695
#8  0x0000556af9366ed4 in SQL_SELECT::check_quick (limit=18446744073709551615, 
    force_quick_range=<optimized out>, thd=0x147d87812018, this=0x147d87848480)
    at /test/10.5_opt/sql/opt_range.h:1655
#9  mysql_update (thd=thd@entry=0x147d87812018, table_list=<optimized out>, fields=..., values=..., 
    conds=<optimized out>, order_num=<optimized out>, order=0x0, limit=18446744073709551615, 
    ignore=false, found_return=0x147dab739f90, updated_return=0x147dab73a060)
    at /test/10.5_opt/sql/sql_update.cc:555
#10 0x0000556af92b9d35 in mysql_execute_command (thd=thd@entry=0x147d87812018)
    at /test/10.5_opt/sql/sql_parse.cc:4401
#11 0x0000556af92c185c in mysql_parse (thd=0x147d87812018, rawbuf=<optimized out>, length=47,
    parser_state=0x147dab73a430, is_com_multi=<optimized out>, is_next_command=<optimized out>)
    at /test/10.5_opt/sql/sql_parse.cc:7993
#12 0x0000556af92b6b65 in dispatch_command (command=command@entry=COM_QUERY, 
    thd=thd@entry=0x147d87812018, 
    packet=packet@entry=0x147d8783a019 "UPDATE t1 SET b=REPEAT(LEFT(b,1),200) WHERE a=1", 
    packet_length=packet_length@entry=47, is_com_multi=is_com_multi@entry=false, 
    is_next_command=is_next_command@entry=false) at /test/10.5_opt/sql/sql_parse.cc:1874
#13 0x0000556af92b4f74 in do_command (thd=0x147d87812018) at /test/10.5_opt/sql/sql_parse.cc:1355
#14 0x0000556af93aab51 in do_handle_one_connection (connect=<optimized out>, 
    connect@entry=0x147da8433958, put_in_cache=put_in_cache@entry=true)
    at /test/10.5_opt/sql/sql_connect.cc:1411
#15 0x0000556af93aaeb4 in handle_one_connection (arg=arg@entry=0x147da8433958)
    at /test/10.5_opt/sql/sql_connect.cc:1313
#16 0x0000556af9719bca in pfs_spawn_thread (arg=0x147da844f218)
    at /test/10.5_opt/storage/perfschema/pfs.cc:2201
#17 0x0000147daa6b46db in start_thread (arg=0x147dab73b700) at pthread_create.c:463
#18 0x0000147da9ab288f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Increasing prio to blocker.

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

Varun clarified that trace is a JSON document, hence Json_writer::add_table_name call, which negates a few things. Lowered prio to critical.

Comment by Varun Gupta (Inactive) [ 2020-06-17 ]

Patch
http://lists.askmonty.org/pipermail/commits/2020-June/014270.html

Comment by Sergei Petrunia [ 2020-06-30 ]

Ok to push

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