[MDEV-21575] Server crashes with SIGSEGV during SELECT DISTINCT on nested views and joins Created: 2020-01-27  Updated: 2020-01-27  Resolved: 2020-01-27

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.3.20, 10.3, 10.4
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Ronald Kurz Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: Crash, optimizer
Environment:

RHEL 7.7

Attachments: Text File test_statements.txt    
Issue Links:
Duplicate
duplicates MDEV-19132 Strange combination of JOIN with NULL... Confirmed

 Description   

MariaDB Server crashed during SELECT – also EXPLAIN will cause the crash:
Error message: ERROR 2013 (HY000): Lost connection to MySQL server during query
System Journal Log:
Jan 27 11:26:44 servername.domain mysqld[120940]: 200127 11:26:44 [ERROR] mysqld got signal 11 ;
Jan 27 11:26:44 servername.domain mysqld[120940]: This could be because you hit a bug. It is also possible that this binary
Jan 27 11:26:44 servername.domain mysqld[120940]: or one of the libraries it was linked against is corrupt, improperly built,
Jan 27 11:26:44 servername.domain mysqld[120940]: or misconfigured. This error can also be caused by malfunctioning hardware.
Jan 27 11:26:44 servername.domain mysqld[120940]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
Jan 27 11:26:44 servername.domain mysqld[120940]: We will try our best to scrape up some info that will hopefully help
Jan 27 11:26:44 servername.domain mysqld[120940]: diagnose the problem, but since we have already crashed,
Jan 27 11:26:44 servername.domain mysqld[120940]: something is definitely wrong and this may fail.
Jan 27 11:26:44 servername.domain mysqld[120940]: Server version: 10.3.20-MariaDB-log
Jan 27 11:26:44 servername.domain mysqld[120940]: key_buffer_size=16777216
Jan 27 11:26:44 servername.domain mysqld[120940]: read_buffer_size=131072
Jan 27 11:26:44 servername.domain mysqld[120940]: max_used_connections=1
Jan 27 11:26:44 servername.domain mysqld[120940]: max_threads=153
Jan 27 11:26:44 servername.domain mysqld[120940]: thread_count=8
Jan 27 11:26:44 servername.domain mysqld[120940]: It is possible that mysqld could use up to
Jan 27 11:26:44 servername.domain mysqld[120940]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2546142 K bytes of memory
Jan 27 11:26:44 servername.domain mysqld[120940]: Hope that's ok; if not, decrease some variables in the equation.
Jan 27 11:26:44 servername.domain mysqld[120940]: Thread pointer: 0x7f25840072b8
Jan 27 11:26:44 servername.domain mysqld[120940]: Attempting backtrace. You can use the following information to find out
Jan 27 11:26:44 servername.domain mysqld[120940]: where mysqld died. If you see no messages after this, something went
Jan 27 11:26:44 servername.domain mysqld[120940]: terribly wrong...
Jan 27 11:26:44 servername.domain mysqld[120940]: stack_bottom = 0x7f261d52ed30 thread_stack 0x49000
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55c09d39b8be]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x55c09ce3859f]
Jan 27 11:26:44 servername.domain mysqld[120940]: sigaction.c:0(__restore_rt)[0x7f26329a3630]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(_Z18cp_buffer_from_refP3THDP5TABLEP12st_table_ref+0x2b)[0x55c09cc9fb9b]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(+0x5faca0)[0x55c09cc9fca0]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0x169)[0x55c09cc902d9]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(_ZN4JOIN10exec_innerEv+0xa7b)[0x55c09ccb1edb]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(_ZN4JOIN4execEv+0x33)[0x55c09ccb20f3]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(_Z12mysql_selectP3THDP10TABLE_LISTjR4ListI4ItemEPS4_jP8st_orderS9_S7_S9_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x11a)[0x55c09ccb224a]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x1cc)[0x55c09ccb2d5c]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(+0x4c2f4c)[0x55c09cb67f4c]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x668b)[0x55c09cc5d03b]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x22b)[0x55c09cc5f51b]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x1ca6)[0x55c09cc62106]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(_Z10do_commandP3THD+0x13e)[0x55c09cc6304e]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x221)[0x55c09cd37111]
Jan 27 11:26:44 servername.domain mysqld[120940]: /usr/sbin/mysqld(handle_one_connection+0x3d)[0x55c09cd371dd]
Jan 27 11:26:44 servername.domain mysqld[120940]: pthread_create.c:0(start_thread)[0x7f263299bea5]
Jan 27 11:26:44 servername.domain mysqld[120940]: /lib64/libc.so.6(clone+0x6d)[0x7f2630d3c8cd]
Jan 27 11:26:44 servername.domain mysqld[120940]: Trying to get some variables.
Jan 27 11:26:44 servername.domain mysqld[120940]: Some pointers may be invalid and cause the dump to abort.
Jan 27 11:26:44 servername.domain mysqld[120940]: Query (0x7f2584017e30): SELECT DISTINCT h9.id FROM haz_mat h9 LEFT JOIN haz_mat_approval_statement_approval_state_view h14 ON h9.id = h14.haz_mat_id LEFT JOIN haz_mat_approval_statement_approval_state_view h15 ON h9.id = h15.haz_mat_id
Jan 27 11:26:44 servername.domain mysqld[120940]: Connection ID (thread ID): 12
Jan 27 11:26:44 servername.domain mysqld[120940]: Status: NOT_KILLED
Jan 27 11:26:44 servername.domain mysqld[120940]: 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=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on
Jan 27 11:26:44 servername.domain mysqld[120940]: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
Jan 27 11:26:44 servername.domain mysqld[120940]: information that should help you find out what is causing the crash.
Jan 27 11:26:44 servername.domain mysqld[120940]: Writing a core file...
Jan 27 11:26:44 servername.domain mysqld[120940]: Working directory at /data/mysql
Jan 27 11:26:44 servername.domain mysqld[120940]: Resource Limits:
Jan 27 11:26:44 servername.domain mysqld[120940]: Limit Soft Limit Hard Limit Units
Jan 27 11:26:44 servername.domain mysqld[120940]: Max cpu time unlimited unlimited seconds
Jan 27 11:26:44 servername.domain mysqld[120940]: Max file size unlimited unlimited bytes
Jan 27 11:26:44 servername.domain mysqld[120940]: Max data size unlimited unlimited bytes
Jan 27 11:26:44 servername.domain mysqld[120940]: Max stack size 8388608 unlimited bytes
Jan 27 11:26:44 servername.domain mysqld[120940]: Max core file size 0 unlimited bytes
Jan 27 11:26:44 servername.domain mysqld[120940]: Max resident set unlimited unlimited bytes
Jan 27 11:26:44 servername.domain mysqld[120940]: Max processes 14989 14989 processes
Jan 27 11:26:44 servername.domain mysqld[120940]: Max open files 16364 16364 files
Jan 27 11:26:44 servername.domain mysqld[120940]: Max locked memory 65536 65536 bytes
Jan 27 11:26:44 servername.domain systemd[1]: mariadb.service: main process exited, code=killed, status=11/SEGV
Jan 27 11:26:44 servername.domain systemd[1]: Unit mariadb.service entered failed state.
Jan 27 11:26:44 servername.domain systemd[1]: mariadb.service failed.
Jan 27 11:26:49 servername.domain systemd[1]: mariadb.service holdoff time over, scheduling restart.
Jan 27 11:26:49 servername.domain systemd[1]: Stopped MariaDB 10.3.20 database server.
Jan 27 11:26:49 servername.domain systemd[1]: Starting MariaDB 10.3.20 database server...
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] /usr/sbin/mysqld (mysqld 10.3.20-MariaDB-log) starting as process 121874 ...
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] Loaded 'server_audit.so' with offset 0x7f8f68de1000
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] Loaded 'simple_password_check.so' with offset 0x7f8f68bde000
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Using Linux native AIO
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Uses event mutexes
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Number of pools: 1
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Using SSE2 crc32 instructions
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, instances = 8, chunk size = 128M
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Completed initialization of buffer pool
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1371316416
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Last binlog file '/datalog/binlog/mariadb-bin.000030', position 37983359
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Creating shared tablespace for temporary tables
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Waiting for purge to start
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: 10.3.20 started; log sequence number 1371316425; transaction id 119256
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysql/ib_buffer_pool
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] Plugin 'FEEDBACK' is disabled.
Jan 27 11:26:50 servername.domain mysqld[121874]: 200127 11:26:50 server_audit: MariaDB Audit Plugin version 1.4.8 STARTED.
Jan 27 11:26:50 servername.domain mysqld[121874]: 200127 11:26:50 server_audit: logging started to the syslog.
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] Recovering after a crash using /datalog/binlog/mariadb-bin
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] Starting crash recovery...
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] Crash recovery finished.
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] Server socket created on IP: '::'.
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] Reading of all Master_info entries succeeded
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] Added new Master_info '' to hash table
Jan 27 11:26:50 servername.domain mysqld[121874]: 2020-01-27 11:26:50 0 [Note] /usr/sbin/mysqld: ready for connections.
Jan 27 11:26:50 servername.domain mysqld[121874]: Version: '10.3.20-MariaDB-log' socket: '/data/mysql/mysql.sock' port: 1800 MariaDB Server
Jan 27 11:26:50 servername.domain systemd[1]: Started MariaDB 10.3.20 database server.

 Comments   
Comment by Alice Sherepa [ 2020-01-27 ]

Could you please add the table structures of tables, invoved in the query, that causes crash, or test case, that shows how to reproduce the bug.

SHOW CREATE TABLE haz_mat; 
SHOW CREATE VIEW haz_mat_approval_statement_approval_state_view ;

Comment by Ronald Kurz [ 2020-01-27 ]

Added Attachement: test_statements.txt with create statements and select statement which crashes the mariadbdb server.

Comment by Alice Sherepa [ 2020-01-27 ]

Thanks a lot! I can reproduce the bug on 10.3-10.4.
It seems to be the same problem as MDEV-19132:

10.3 7e8a58020bc2b0dcac959

 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#5  0x00007fb0079d3535 in __GI_abort () at abort.c:79
 
#6  0x00007fb0079d340f in __assert_fail_base (fmt=0x7fb007b35ee0 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x556439e6edd8 "join->best_read < double(1.79769313486231570814527423731704357e+308L)", file=0x556439e6dec8 "/10.3/sql/sql_select.cc", line=8107, function=<optimized out>) at assert.c:92
 
#7  0x00007fb0079e1102 in __GI___assert_fail (assertion=0x556439e6edd8 "join->best_read < double(1.79769313486231570814527423731704357e+308L)", file=0x556439e6dec8 "/10.3/sql/sql_select.cc", line=8107, function=0x556439e719c0 <greedy_search(JOIN*, unsigned long long, unsigned int, unsigned int, unsigned int)::__PRETTY_FUNCTION__> "bool greedy_search(JOIN*, table_map, uint, uint, uint)") at assert.c:101
 
#8  0x000055643922af9a in greedy_search (join=0x7fafb42a7db8, remaining_tables=2064895, search_depth=62, prune_level=1, use_cond_selectivity=1) at /10.3/sql/sql_select.cc:8107
 
#9  0x000055643922a205 in choose_plan (join=0x7fafb42a7db8, join_tables=2064895) at /10.3/sql/sql_select.cc:7675
 
#10 0x0000556439222b6c in make_join_statistics (join=0x7fafb42a7db8, tables_list=..., keyuse_array=0x7fafb42a80a8) at /10.3/sql/sql_select.cc:5143
 
#11 0x00005564392174f2 in JOIN::optimize_inner (this=0x7fafb42a7db8) at /10.3/sql/sql_select.cc:1942
 
#12 0x0000556439215a25 in JOIN::optimize (this=0x7fafb42a7db8) at /10.3/sql/sql_select.cc:1488
 
#13 0x000055643921fa22 in mysql_select (thd=0x7fafb4000d50, tables=0x7fafb4012e10, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748609, result=0x7fafb42a7d90, unit=0x7fafb4004c18, select_lex=0x7fafb40053a0) at /10.3/sql/sql_select.cc:4283
 
#14 0x00005564392112fc in handle_select (thd=0x7fafb4000d50, lex=0x7fafb4004b58, result=0x7fafb42a7d90, setup_tables_done_option=0) at /10.3/sql/sql_select.cc:370
 
#15 0x00005564391d9000 in execute_sqlcom_select (thd=0x7fafb4000d50, all_tables=0x7fafb4012e10) at /10.3/sql/sql_parse.cc:6294
 
#16 0x00005564391cfa75 in mysql_execute_command (thd=0x7fafb4000d50) at /10.3/sql/sql_parse.cc:3821
 
#17 0x00005564391dd2dc in mysql_parse (thd=0x7fafb4000d50, rawbuf=0x7fafb4012a78 "SELECT DISTINCT h9.id FROM haz_mat h9\nLEFT JOIN haz_mat_approval_statement_approval_state_view h14 ON h9.id = h14.haz_mat_id\nLEFT JOIN haz_mat_approval_statement_approval_state_view h15 ON h9.id = h15"..., length=211, parser_state=0x7fb000b8d5c0, is_com_multi=false, is_next_command=false) at /10.3/sql/sql_parse.cc:7818
 
#18 0x00005564391c9f49 in dispatch_command (command=COM_QUERY, thd=0x7fafb4000d50, packet=0x7fafb4008ed1 "SELECT DISTINCT h9.id FROM haz_mat h9\nLEFT JOIN haz_mat_approval_statement_approval_state_view h14 ON h9.id = h14.haz_mat_id\nLEFT JOIN haz_mat_approval_statement_approval_state_view h15 ON h9.id = h15"..., packet_length=211, is_com_multi=false, is_next_command=false) at /10.3/sql/sql_parse.cc:1855
 
#19 0x00005564391c889c in do_command (thd=0x7fafb4000d50) at /10.3/sql/sql_parse.cc:1401
 
#20 0x000055643933e84d in do_handle_one_connection (connect=0x55643c1e81b0) at /10.3/sql/sql_connect.cc:1403
 
#21 0x000055643933e5af in handle_one_connection (arg=0x55643c1e81b0) at /10.3/sql/sql_connect.cc:1308
 
#22 0x0000556439cd3475 in pfs_spawn_thread (arg=0x55643c174340) at /10.3/storage/perfschema/pfs.cc:1869
 
#23 0x00007fb0080fefa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
 
#24 0x00007fb007aaa4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

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