[MCOL-1951] Crash when MySQL aggregate UDF is called against Columnstore table Created: 2018-11-20  Updated: 2020-08-25  Resolved: 2019-04-02

Status: Closed
Project: MariaDB ColumnStore
Component/s: None
Affects Version/s: 1.1.5, 1.1.6, 1.1.7
Fix Version/s: 1.1.0, 1.2.4

Type: Bug Priority: Critical
Reporter: Valerii Kravchuk Assignee: Zdravelina Sokolovska (Inactive)
Resolution: Fixed Votes: 1
Labels: None

Sprint: 2019-01, 2019-02, 2019-03

 Description   

MariaDB ColumnStore (mysqld porocess) crashes when any "normal" MySQL aggregate UDF is called against ColumnStore table. We can use avgcost() example function form udf_example.so:

openxs@ao756:~$ mysql -uroot --socket=/usr/local/mariadb/columnstore/mysql/lib/m    ysql/mysql.sock test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A
 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 13
Server version: 5.5.5-10.2.15-MariaDB-log Columnstore 1.1.5-1
 
Copyright (c) 2009-2018 Percona LLC and/or its affiliates
Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.
 
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
mysql> CREATE AGGREGATE FUNCTION avgcost RETURNS REAL
    ->   SONAME 'udf_example.so';
Query OK, 0 rows affected (0.00 sec)
 
mysql> create table tcs2(id int, val int, val2 real) engine=ColumnStore;
Query OK, 0 rows affected (5.19 sec)
 
mysql> insert into tcs2 values(1,1,0.1), (2,2,0.2);
Query OK, 2 rows affected (1.05 sec)
Records: 2  Duplicates: 0  Warnings: 0
 
mysql> select avgcost(val,val2) from tcs2;
ERROR 2013 (HY000): Lost connection to MySQL server during query

In the error log we see:

Thread pointer: 0x7fe3c8078ce8
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 = 0x7fe418f91e98 thread_stack 0x80000
/usr/local/mariadb/columnstore/mysql//bin/mysqld(my_print_stacktrace+0x29)[0x7fe4543be219]
/usr/local/mariadb/columnstore/mysql//bin/mysqld(handle_fatal_signal+0x33d)[0x7fe453ee620d]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7fe451b85330]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7fe450fc2c37]
linux/raise.c:56(__GI_raise)[0x7fe450fc6028]
/usr/lib/x86_64-linux-gnu/libstdc++.so.6(_ZN9__gnu_cxx27__verbose_terminate_handlerEv+0x155)[0x7fe4518d1535]
/usr/lib/x86_64-linux-gnu/libstdc++.so.6(+0x5e6d6)[0x7fe4518cf6d6]
/usr/lib/x86_64-linux-gnu/libstdc++.so.6(+0x5e703)[0x7fe4518cf703]
/usr/lib/x86_64-linux-gnu/libstdc++.so.6(+0x5e922)[0x7fe4518cf922]
/usr/local/mariadb/columnstore/lib/libudfsdk.so.1(_ZN8mcsv1sdk12mcsv1Context11getFunctionEv+0x1e1)[0x7fe44d933de1]
/usr/local/mariadb/columnstore/mysql/lib/plugin/libcalmysql.so(_ZN11cal_impl_if20buildAggregateColumnEP4ItemRNS_12gp_walk_infoE+0x11d1)[0x7fe44fcd7211]
/usr/local/mariadb/columnstore/mysql/lib/plugin/libcalmysql.so(_ZN11cal_impl_if13getSelectPlanERNS_12gp_walk_infoER13st_select_lexRN5boost10shared_ptrIN8execplan26CalpontSelectExecutionPlanEEEb+0x2775)[0x7fe44fce4ed5]
/usr/local/mariadb/columnstore/mysql/lib/plugin/libcalmysql.so(_ZN11cal_impl_if11cp_get_planEP3THDRN5boost10shared_ptrIN8execplan26CalpontSelectExecutionPlanEEE+0x8ad)[0x7fe44fcf170d]
/usr/local/mariadb/columnstore/mysql/lib/plugin/libcalmysql.so(_Z24ha_calpont_impl_rnd_initP5TABLE+0x607)[0x7fe44fc9d517]
/usr/local/mariadb/columnstore/mysql//bin/mysqld(_ZN4JOIN13exec_infinidbEv+0x233)[0x7fe453d978e3]
sql/handler.h:2839(handler::ha_rnd_init(bool))[0x7fe453dbc8ee]
sql/sql_select.cc:3626(JOIN::exec_inner())[0x7fe453dbd4d9]
sql/sql_select.cc:3404(JOIN::exec())[0x7fe453dbd6ee]
sql/sql_select.cc:4053(mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*))[0x7fe453dbe2cb]
sql/sql_select.cc:376(handle_select(THD*, LEX*, select_result*, unsigned long))[0x7fe453d6fb60]
sql/sql_parse.cc:3993(mysql_execute_command(THD*))[0x7fe453d7118f]
sql/sql_parse.cc:7981(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x7fe453d72273]
sql/sql_parse.cc:10238(idb_parse_vtable(THD*, String&, THD::infinidb_state))[0x7fe453d737ee]
sql/sql_parse.cc:10793(idb_vtable_process(THD*, unsigned long long, Statement*))[0x7fe453d76b1a]
sql/sql_parse.cc:1837(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x7fe453d77bd8]
sql/sql_parse.cc:1395(do_command(THD*))[0x7fe453e30f6c]
sql/sql_connect.cc:1335(do_handle_one_connection(CONNECT*))[0x7fe453e31084]
nptl/pthread_create.c:312(start_thread)[0x7fe451b7d184]
x86_64/clone.S:113(clone)[0x7fe45108a03d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fe3c801beb8): create temporary table infinidb_vtable.$vtable_14 engine = aria as select avgcost(val,val2) from tcs2
...

udf_sample.so is built in the process of building ColumnStore server:

openxs@ao756:~$ ls -l ~/git/mariadb-columnstore-server/sql/udf_example.*
-rw-rw-r-- 1 openxs openxs 33714 чер 20 20:11 /home/openxs/git/mariadb-columnstore-server/sql/udf_example.c
-rw-rw-r-- 1 openxs openxs   458 лют  8  2017 /home/openxs/git/mariadb-columnstore-server/sql/udf_example.def
-rwxrwxr-x 1 openxs openxs 54547 сер 15 07:50 /home/openxs/git/mariadb-columnstore-server/sql/udf_example.so

I understand that (aggregate) UDFs for ColumnStore are created using different SDK etc, but it is not normal to accept creating function and then just crash when it is called. I'd expect some error message explaining that UDF is not defined at ColumnStore level instead.



 Comments   
Comment by Andrew Hutchings (Inactive) [ 2018-11-20 ]

I believe this ticket basically says that there is a MariaDB UDF without a corresponding ColumnStore one. So when the UDF is executed against a ColumnStore table we get a crash (likely an uncaught exception).

If this is correct then the correct behaviour would be to error here instead of crash.

Comment by David Hall (Inactive) [ 2018-11-20 ]

The code is designed to generate an error in this case, not crash.

Comment by David Hall (Inactive) [ 2019-03-06 ]

It's throwing a logic_error assuming the caller would catch and raise the error to the user. Seems nobody catches it.

Comment by David Hall (Inactive) [ 2019-03-06 ]

New error:
ERROR 1178 (42000): The storage engine for the table doesn't support mcsv1Context::getFunction: avgcost is undefined in Columnstore

Comment by Zdravelina Sokolovska (Inactive) [ 2019-03-28 ]

checked with target 1.2.4 / versionEngineID f2e6d8d
mysqld is not crashing , it is returned Error :
ERROR 1178 (42000): The storage engine for the table doesn't support error building Aggregate Function: mcsv1Context::getFunction:

 
MariaDB [(none)]> CREATE AGGREGATE FUNCTION avgcost RETURNS REAL SONAME 'udf_example.so';
Query OK, 0 rows affected (0.001 sec)
 
MariaDB [(none)]> use foo ;
Database changed
MariaDB [foo]> create table tcs2(id int, val int, val2 real) engine=ColumnStore;
Query OK, 0 rows affected (1.011 sec)
 
MariaDB [foo]> insert into tcs2 values(1,1,0.1), (2,2,0.2);
Query OK, 2 rows affected (0.344 sec)
Records: 2  Duplicates: 0  Warnings: 0
 
MariaDB [foo]> select avgcost(val,val2) from tcs2;
ERROR 1178 (42000): The storage engine for the table doesn't support error building Aggregate Function: mcsv1Context::getFunction: avgcost is undefined
MariaDB [foo]>

Comment by Zdravelina Sokolovska (Inactive) [ 2019-03-28 ]

the problem is recreated on 1.1.7 ; 1.1.8 is not yet opened

 
MariaDB [(none)]> CREATE AGGREGATE FUNCTION avgcost RETURNS REAL SONAME 'udf_example.so';
Query OK, 0 rows affected (0.00 sec)
MariaDB [(none)]> create database foo ;
Query OK, 1 row affected (0.00 sec)
MariaDB [(none)]> use foo ;
Database changed
MariaDB [foo]> create table tcs2(id int, val int, val2 real) engine=ColumnStore;
Query OK, 0 rows affected (0.37 sec)
 
MariaDB [foo]> insert into tcs2 values(1,1,0.1), (2,2,0.2);
Query OK, 2 rows affected (0.40 sec)
Records: 2  Duplicates: 0  Warnings: 0
 
MariaDB [foo]> select avgcost(val,val2) from tcs2;
ERROR 2013 (HY000): Lost connection to MySQL server during query
 
 
Version: '10.2.22-MariaDB-log'  socket: '/usr/local/mariadb/columnstore/mysql/lib/mysql/mysql.sock'  port: 3306  Columnstore 1.1.7-1
terminate called after throwing an instance of 'std::logic_error'
  what():  mcsv1Context::getFunction: avgcost is undefined
190328 17:15:07 [ERROR] mysqld got signal 6 ;
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.2.22-MariaDB-log
key_buffer_size=536870912
read_buffer_size=4194304
max_used_connections=1
max_threads=153
thread_count=8
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1780903 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7f7ee4000a88
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 = 0x7f7f31da4d98 thread_stack 0x80000
/usr/local/mariadb/columnstore/mysql//bin/mysqld(my_print_stacktrace+0x29)[0x560c83357cc9]
mysys/stacktrace.c:268(my_print_stacktrace)[0x560c82e7b17d]
sigaction.c:0(__restore_rt)[0x7f7f637075e0]
:0(__GI_raise)[0x7f7f615ec1f7]
:0(__GI_abort)[0x7f7f615ed8e8]
/lib64/libstdc++.so.6(_ZN9__gnu_cxx27__verbose_terminate_handlerEv+0x165)[0x7f7f61ef2ac5]
/lib64/libstdc++.so.6(+0x5ea36)[0x7f7f61ef0a36]
/lib64/libstdc++.so.6(+0x5ea63)[0x7f7f61ef0a63]
/lib64/libstdc++.so.6(+0x5ec83)[0x7f7f61ef0c83]
udfsdk/mcsv1_udaf.cpp:153(mcsv1sdk::mcsv1Context::getFunction())[0x7f7f5c913321]
mysql/ha_calpont_execplan.cpp:3987(cal_impl_if::buildAggregateColumn(Item*, cal_impl_if::gp_walk_info&))[0x7f7f5f0f84ec]
mysql/ha_calpont_execplan.cpp:5345(cal_impl_if::getSelectPlan(cal_impl_if::gp_walk_info&, st_select_lex&, boost::shared_ptr<execplan::CalpontSelectExecutionPlan>&, bool))[0x7f7f5f1063d5]
mysql/ha_calpont_execplan.cpp:6959(cal_impl_if::cp_get_plan(THD*, boost::shared_ptr<execplan::CalpontSelectExecutionPlan>&))[0x7f7f5f112c27]
mysql/ha_calpont_impl.cpp:2783(ha_calpont_impl_rnd_init(TABLE*))[0x7f7f5f0bdb59]
sql/handler.h:2851(handler::ha_rnd_init(bool))[0x560c82d3f683]
sql/sql_select.cc:3679(JOIN::exec_inner())[0x560c82d640ed]
sql/sql_select.cc:3457(JOIN::exec())[0x560c82d64c79]
sql/sql_select.cc:4106(mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*))[0x560c82d64e8e]
sql/sql_select.cc:376(handle_select(THD*, LEX*, select_result*, unsigned long))[0x560c82d65a6b]
sql/sql_parse.cc:4011(mysql_execute_command(THD*))[0x560c82d19263]
sql/sql_parse.cc:8072(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x560c82d1a3b0]
sql/sql_class.h:2806(THD::set_row_count_func(long long))[0x560c82d1ad9b]
sql/sql_parse.cc:10895(idb_vtable_process(THD*, unsigned long long, Statement*))[0x560c82d1c322]
sql/sql_parse.cc:1846(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x560c82d1e48a]
sql/sql_parse.cc:1433(do_command(THD*))[0x560c82d20014]
sql/sql_connect.cc:1336(do_handle_one_connection(CONNECT*))[0x560c82ddbe24]
sql/sql_connect.cc:1244(handle_one_connection)[0x560c82ddbee4]
pthread_create.c:0(start_thread)[0x7f7f636ffe25]
/lib64/libc.so.6(clone+0x6d)[0x7f7f616af34d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f7ee40104d0): is an invalid pointer
Connection ID (thread ID): 10
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_pushdown=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,subquery_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_buffer_size=off,table_elimination=off,extended_keys=off,exists_to_in=on,orderby_uses_equalities=off,condition_pushdown_for_derived=off
 
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: create temporary table infinidb_vtable.$vtable_10 engine = aria as select avgcost(val,val2) from tcs2
 
190328 17:15:08 Columnstore: Started; Version: 1.1.7-1
190328 17:15:08 Columnstore: Started; Version: 1.1.7-1
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Uses event mutexes
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Compressed tables use zlib 1.2.7
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Using Linux native AIO
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Number of pools: 1
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Using SSE2 crc32 instructions
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Completed initialization of buffer pool
2019-03-28 17:15:08 139907530721024 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Highest supported file format is Barracuda.
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1644353
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Last binlog file '/usr/local/mariadb/columnstore/mysql/db/mysql-bin.000001', position 7970
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: Waiting for purge to start
2019-03-28 17:15:08 139908693301376 [Note] InnoDB: 5.7.25 started; log sequence number 1644362
2019-03-28 17:15:08 139907368457984 [Note] InnoDB: Loading buffer pool(s) from /usr/local/mariadb/columnstore/mysql/db/ib_buffer_pool
2019-03-28 17:15:08 139907368457984 [Note] InnoDB: Buffer pool(s) load completed at 190328 17:15:08
2019-03-28 17:15:08 139908693301376 [Note] Plugin 'FEEDBACK' is disabled.
2019-03-28 17:15:08 139908693301376 [Warning] /usr/local/mariadb/columnstore/mysql//bin/mysqld: unknown variable 'loose-server_audit_syslog_info=columnstore-1'
2019-03-28 17:15:08 139908693301376 [Note] Recovering after a crash using /usr/local/mariadb/columnstore/mysql/db/mysql-bin
2019-03-28 17:15:08 139908693301376 [Note] Starting crash recovery...
2019-03-28 17:15:08 139908693301376 [Note] Crash recovery finished.
2019-03-28 17:15:08 139908693301376 [Note] Server socket created on IP: '::'.
2019-03-28 17:15:08 139908693301376 [ERROR] mysqld: Table './mysql/func' is marked as crashed and should be repaired
2019-03-28 17:15:08 139908693301376 [ERROR] mysqld: Table 'func' is marked as crashed and should be repaired
2019-03-28 17:15:08 139908693301376 [Warning] Checking table:   './mysql/func'
2019-03-28 17:15:08 139908693301376 [ERROR] mysql.func: 1 client is using or hasn't closed the table properly
2019-03-28 17:15:08 139908693301376 [Note] Reading of all Master_info entries succeded
2019-03-28 17:15:08 139908693301376 [Note] Added new Master_info '' to hash table
2019-03-28 17:15:08 139908693301376 [Note] /usr/local/mariadb/columnstore/mysql//bin/mysqld: ready for connections.
Version: '10.2.22-MariaDB-log'  socket: '/usr/local/mariadb/columnstore/mysql/lib/mysql/mysql.sock'  port: 3306  Columnstore 1.1.7-1

Comment by David Hall (Inactive) [ 2019-03-28 ]

The develop-1.1 branch is up to date. The latest nightly should work.

Comment by Zdravelina Sokolovska (Inactive) [ 2019-03-29 ]

checked with cs dev 1.1 versionEngineID 0f04bb4
mysqld is not crashing , it is returned Error :
ERROR 1178 (42000): The storage engine for the table doesn't support error building Aggregate Function: mcsv1Context::getFunction:

MariaDB [(none)]> CREATE AGGREGATE FUNCTION avgcost RETURNS REAL SONAME 'udf_example.so';
Query OK, 0 rows affected (0.00 sec)
 
MariaDB [foo]> create table tcs2(id int, val int, val2 real) engine=ColumnStore;
Query OK, 0 rows affected (0.38 sec)
 
MariaDB [foo]> insert into tcs2 values(1,1,0.1), (2,2,0.2);
Query OK, 2 rows affected (0.44 sec)
Records: 2  Duplicates: 0  Warnings: 0
 
MariaDB [foo]> select avgcost(val,val2) from tcs2;
ERROR 1178 (42000): The storage engine for the table doesn't support mcsv1Context::getFunction: avgcost is undefined

Comment by Zdravelina Sokolovska (Inactive) [ 2019-04-02 ]

builds verified :
1.1.8-1 versionEngineID
069f9e9
1.2.4-1 versionEngineID
7b1f461

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