[MCOL-3897] Select Handler processing causes SEGV in MDB intermittenly trying to start scan operation. Created: 2020-03-21  Updated: 2021-02-01  Resolved: 2021-02-01

Status: Closed
Project: MariaDB ColumnStore
Component/s: MDB Plugin
Affects Version/s: 1.4.3
Fix Version/s: 1.4.5

Type: Task Priority: Major
Reporter: Roman Assignee: Unassigned
Resolution: Cannot Reproduce Votes: 0
Labels: None
Environment:

Docker for Sky and test VM installations with ent packages.



 Description   

According with the crash trace the crash trace contains two assignments(thanks to compiler optimizer and CPU microinstructions reordering) and it is not clear which one causes SEGV signal. The one from calpontsystemcatalog.h is hard to research. The second from ha_mcs_impl.cpp is more readable. Short explanation. 1.4 was supposed to allow to fallback from Select Handler to slower execution paths and query scan that must be run once only was delayed until SH_next()[1]. It seems that if condition that guards query scan activation fails in some cases and doesn't populate ci->tableMap[table] so later the assignment at 5428 causes SEGV.

[root@drrtuy-centos-7-main ~]# addr2line -e /usr/lib/debug/usr/lib64/mysql/plugin/ha_columnstore.so.debug 0x7a454
addr2line: Ошибка в dwarf: Смещение (327357183) больше или равно размеру .debug_str (2005393).
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 106.
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 107.
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 107.
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 105.
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 115.
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 115.
/usr/src/debug/MariaDB-10.4.12-6/src_0/storage/columnstore/columnstore/dbcon/mysql/ha_mcs_impl.cpp:5428
[root@drrtuy-centos-7-main ~]# vim /usr/src/debug/MariaDB-10.4.12-6/src_0/storage/columnstore/columnstore/dbcon/mysql/ha_mcs_impl.cpp
 
[root@drrtuy-centos-7-main ~]# addr2line -e /usr/lib/debug/usr/lib64/mysql/plugin/ha_columnstore.so.debug 0x6f665
addr2line: Ошибка в dwarf: Смещение (327357183) больше или равно размеру .debug_str (2005393).
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 106.
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 107.
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 107.
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 105.
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 115.
addr2line: Ошибка в dwarf: Невозможно найти укороченный номер 115.
/usr/src/debug/MariaDB-10.4.12-6/src_0/storage/columnstore/columnstore/dbcon/execplan/calpontsystemcatalog.h:304

Here is the crash trace.

200319 16:57:50 [ERROR] mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
Server version: 10.4.12-6-MariaDB-enterprise-log
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=13
max_threads=242
thread_count=22
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 229960 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x7fa924c56008
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7fa9c104ecf0 thread_stack 0x49000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55a484ade26e]
/usr/sbin/mysqld(handle_fatal_signal+0x30f)[0x55a48456716f]
sigaction.c:0(__restore_rt)[0x7fa9d9f9f5f0]
/lib64/libstdc++.so.6(_ZNSs6assignERKSs+0x2c)[0x7fa9d83f4d4c]
/usr/lib64/mysql/plugin/ha_columnstore.so(+0x6f665)[0x7fa9c9515665]
/usr/lib64/mysql/plugin/ha_columnstore.so(_Z22ha_cs_impl_select_nextPhP5TABLE+0x4d4)[0x7fa9c9520454]
/usr/sbin/mysqld(_ZN15Pushdown_select7executeEv+0x4a)[0x55a4843d1c6a]
/usr/sbin/mysqld(_ZN4JOIN10exec_innerEv+0x34a)[0x55a4843b3afa]
/usr/sbin/mysqld(_ZN4JOIN4execEv+0x33)[0x55a4843b45a3]
/usr/sbin/mysqld(_Z12mysql_selectP3THDP10TABLE_LISTjR4ListI4ItemEPS4_jP8st_orderS9_S7_S9_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x186)[0x55a4843b28b6]
/usr/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x1c7)[0x55a4843b3417]
/usr/sbin/mysqld(+0x5a2bb4)[0x55a484249bb4]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x4675)[0x55a484357775]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x222)[0x55a48435c6b2]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x1c07)[0x55a48435f517]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x11c)[0x55a484360bec]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x221)[0x55a484441a51]
/usr/sbin/mysqld(handle_one_connection+0x3d)[0x55a484441b0d]
pthread_create.c:0(start_thread)[0x7fa9d9f97e65]
/lib64/libc.so.6(clone+0x6d)[0x7fa9d7d6488d]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fa924c88020): is an invalid pointer
Connection ID (thread ID): 30
Status: NOT_KILLED
Optimizer switch: index_merge=off,index_merge_union=off,index_merge_sort_union=off,index_merge_intersection=off,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pu
shdown=off,derived_merge=off,derived_with_keys=off,firstmatch=off,loosescan=off,materialization=off,in_to_exists=on,semijoin=off,partial_match_rowid_merge=off,partial_match_table_scan=off,subque
ry_cache=off,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=off,semijoin_with_cache=off,join_cache_incremental=off,join_cache_hashed=off,join_cache_bka=off,optimize_join_buff
er_size=off,table_elimination=off,extended_keys=off,exists_to_in=off,orderby_uses_equalities=off,condition_pushdown_for_derived=on,split_materialized=off,condition_pushdown_for_subquery=off,rowi
d_filter=off,condition_pushdown_from_having=on
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
We think the query pointer is invalid, but we will try to print it anyway. 
Query: select 
    a.airline,
    count(*) 
from 
    travel.airlines a inner join
    travel_history.flights f on a.iata_code = f.carrier
where 
    year = 2019 and month = 3
group by
    a.airline
Writing a core file...
Working directory at /var/lib/mysql
Resource Limits:
Limit                     Soft Limit           Hard Limit           Units     
Max cpu time              unlimited            unlimited            seconds   
Max file size             unlimited            unlimited            bytes     
Max data size             unlimited            unlimited            bytes     
Max stack size            8388608              unlimited            bytes     
Max core file size        unlimited            unlimited            bytes     
Max resident set          unlimited            unlimited            bytes     
Max processes             unlimited            unlimited            processes 
Max open files            1048576              1048576              files     
Max locked memory         65536                65536                bytes     
Max address space         unlimited            unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       59997                59997                signals   
Max msgqueue size         819200               819200               bytes     
Max nice priority         0                    0                    
Max realtime priority     0                    0                    
Max realtime timeout      unlimited            unlimited            us        
Core pattern: core.%e.%p.%t
2020-03-19 16:57:51 0 [Warning] Plugin 'Columnstore' is of maturity level gamma while the server is stable
2020-03-19 16:57:51 0 [Warning] Plugin 'COLUMNSTORE_COLUMNS' is of maturity level gamma while the server is stable
2020-03-19 16:57:51 0 [Warning] Plugin 'COLUMNSTORE_TABLES' is of maturity level gamma while the server is stable
2020-03-19 16:57:51 0 [Warning] Plugin 'COLUMNSTORE_FILES' is of maturity level gamma while the server is stable
2020-03-19 16:57:51 0 [Warning] Plugin 'COLUMNSTORE_EXTENTS' is of maturity level gamma while the server is stable
200319 16:57:51 Columnstore: Started; Version: 1.4.3-1
2020-03-19 16:57:51 0 [Note] InnoDB: Using Linux native AIO
2020-03-19 16:57:51 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-03-19 16:57:51 0 [Note] InnoDB: Uses event mutexes
2020-03-19 16:57:51 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
2020-03-19 16:57:51 0 [Note] InnoDB: Number of pools: 1
2020-03-19 16:57:51 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-03-19 16:57:51 0 [Note] InnoDB: Initializing buffer pool, total size = 2G, instances = 4, chunk size = 128M
2020-03-19 16:57:51 0 [Note] InnoDB: Completed initialization of buffer pool
2020-03-19 16:57:51 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-03-19 16:57:51 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1091647
2020-03-19 16:57:51 0 [Note] InnoDB: Last binlog file './mysql-bin.000057', position 826750773
2020-03-19 16:57:51 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-03-19 16:57:51 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2020-03-19 16:57:51 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-03-19 16:57:51 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-03-19 16:57:51 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-03-19 16:57:51 0 [Note] InnoDB: Waiting for purge to start
2020-03-19 16:57:51 0 [Note] InnoDB: 10.4.12 started; log sequence number 1091656; transaction id 2545
2020-03-19 16:57:51 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2020-03-19 16:57:51 0 [Note] Plugin 'S3' is disabled.
2020-03-19 16:57:51 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-03-19 16:57:51 server_audit: MariaDB Audit Plugin version 2.0.2 STARTED.
2020-03-19 16:57:51 server_audit: Query cache is enabled with the TABLE events. Some table reads can be veiled.
2020-03-19 16:57:51 0 [Note] InnoDB: Buffer pool(s) load completed at 200319 16:57:51
2020-03-19 16:57:51 0 [Note] Recovering after a crash using mysql-bin
2020-03-19 16:57:51 0 [Note] Starting crash recovery...
2020-03-19 16:57:51 0 [Note] Crash recovery finished.
2020-03-19 16:57:51 0 [Note] Server socket created on IP: '::'.
2020-03-19 16:57:51 0 [Note] Reading of all Master_info entries succeeded
2020-03-19 16:57:51 0 [Note] Added new Master_info '' to hash table
2020-03-19 16:57:51 0 [Warning] Recovery from master pos 4 and file mysql-bin.000058.
2020-03-19 16:57:51 10 [Note] Slave I/O thread: Start asynchronous replication to master 'skysql_replication@htap-demo-1-mariadb-maxscale-replication:3309' in log 'mysql-bin.000058' at position 
4
2020-03-19 16:57:51 11 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000058' at position 4, relay log './mysql-relay-bin.000001' position: 4; GTID position '1-1-893
'
2020-03-19 16:57:51 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.4.12-6-MariaDB-enterprise-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Enterprise Server
2020-03-19 16:57:51 10 [ERROR] Slave I/O: error connecting to master 'skysql_replication@htap-demo-1-mariadb-maxscale-replication:3309' - retry-time: 60  maximum-retries: 86400  message: failed 
to create new session, Internal MariaDB error code: 1045
2020-03-19 16:57:53 12 [Warning] IP address '10.0.5.2' could not be resolved: Name or service not known
2020-03-19 16:58:51 10 [Note] Slave I/O thread: connected to master 'skysql_replication@htap-demo-1-mariadb-maxscale-replication:3309',replication starts at GTID position '1-1-893'
2020-03-19 16:58:51 31 [Note] Start binlog_dump to slave_server(1), pos(mysql-bin.000058, 4)

1. but the mechanism was considered errorprone and vague from MDB's perspective [2]. So it was abandoned.
2. create_SH() should't execute the query. This should be done in init_SH().



 Comments   
Comment by Roman [ 2020-03-21 ]

I didn't reproduce the issue using MDB client connection though so I asked the ways to reproduce.

Comment by Roman [ 2020-03-21 ]

Here is the translation of addr2line errors from russian:

addr2line: Error in dwarf: Offset (327357183) is greater than or equal to the size of .debug_str (2005393).
addr2line: Error in dwarf: Unable to find shortened number 106.

Generated at Thu Feb 08 02:46:16 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.