[MDEV-6345] mariadb with oq_graph server crash when running query from 2+ connections Created: 2014-06-16  Updated: 2015-05-03  Resolved: 2015-05-03

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - OQGRAPH
Affects Version/s: 10.0.12
Fix Version/s: 10.0.18

Type: Bug Priority: Major
Reporter: Gavrila Assignee: Andrew McDonnell
Resolution: Fixed Votes: 0
Labels: oqgraph
Environment:

Debian 7.5
Linux duduta 3.2.0-4-amd64 #1 SMP Debian 3.2.57-3+deb7u1 x86_64 GNU/Linux
libmariadbclient18
mariadb-client-10.0
mariadb-client-core-10.0
mariadb-common
mariadb-oqgraph-engine-10.0
mariadb-server-10.0
mariadb-server-core-10.0

Issue Links:
Relates
relates to MDEV-6282 OQGraph crashes under load Closed
relates to MDEV-6784 OQGRAPH: External Connection Crashes ... Closed

 Description   

After following the example at https://mariadb.com/kb/en/oqgraph-examples/

when I run a query ""SELECT * FROM oq_graph WHERE latch='breadth_first' AND origid=1 AND destid=6;"
from two or more client connections I get ERROR 2013 (HY000): Lost connection to MySQL server during query

root@duduta:/home/unics# mysqld --debug
 
140616 11:47:26 [Warning] 'debug' is disabled in this build
 
140616 11:47:26 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
140616 11:47:26 [Note] InnoDB: The InnoDB memory heap is disabled
 
140616 11:47:26 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
140616 11:47:26 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
140616 11:47:26 [Note] InnoDB: Using Linux native AIO
 
140616 11:47:26 [Note] InnoDB: Using CPU crc32 instructions
 
140616 11:47:26 [Note] InnoDB: Initializing buffer pool, size = 256.0M
 
140616 11:47:26 [Note] InnoDB: Completed initialization of buffer pool
 
140616 11:47:26 [Note] InnoDB: Highest supported file format is Barracuda.
 
140616 11:47:26 [Note] InnoDB: 128 rollback segment(s) are active.
 
140616 11:47:26 [Note] InnoDB: Waiting for purge to start
 
140616 11:47:26 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.17-65.0 started; log sequence number 1411674093
 
140616 11:47:26 [Note] Plugin 'FEEDBACK' is disabled.
 
140616 11:47:26 [Note] Server socket created on IP: '127.0.0.1'.
 
140616 11:47:26 [Note] Event Scheduler: Loaded 0 events
 
140616 11:47:26 [Note] Reading of all Master_info entries succeded
 
140616 11:47:26 [Note] Added new Master_info '' to hash table
 
140616 11:47:26 [Note] mysqld: ready for connections.
 
Version: '10.0.12-MariaDB-1~wheezy-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
 
2014-06-16 11:47:47 7f40838e2700  InnoDB: Assertion failure in thread 139915061765888 in file ha_innodb.cc line 9254
 
InnoDB: Failing assertion: prebuilt->trx == thd_to_trx(ha_thd())
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
 
InnoDB: If you get repeated assertion failures or crashes, even
 
InnoDB: immediately after the mysqld startup, there may be
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
140616 11:47:47 [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 http://kb.askmonty.org/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.0.12-MariaDB-1~wheezy-log
 
key_buffer_size=134217728
 
read_buffer_size=2097152
 
max_used_connections=2
 
max_threads=102
 
thread_count=2
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 759849 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0x7f4060993008
 
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 = 0x7f40838e1df0 thread_stack 0x48000
 
addr2line: 'mysqld': No such file
 
mysqld(my_print_stacktrace+0x2b)[0x7f40844736cb]
 
mysqld(handle_fatal_signal+0x422)[0x7f4084006482]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf030)[0x7f408365a030]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x7f4081cb5475]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x180)[0x7f4081cb86f0]
 
mysqld(+0x710e89)[0x7f4084199e89]
 
/usr/lib/mysql/plugin/ha_oqgraph.so(_ZNK8oqgraph36cursor15record_positionEv+0x36)[0x7f407f9d7e36]
 
/usr/lib/mysql/plugin/ha_oqgraph.so(_ZNK8oqgraph310cursor_ptrneERKS0_+0x1b)[0x7f407f9d7ecb]
 
/usr/lib/mysql/plugin/ha_oqgraph.so(_ZN5boost19breadth_first_visitIN8oqgraph35graphENS_5queueIySt5dequeIySaIyEEEENS_11bfs_visitorISt4pairINS_20predecessor_recorderINS_24associative_property_mapINS_9unordered13unordered_mapIyyNS_4hashIyEESt8equal_toIyESaIS9_IKyyEEEEEENS_12on_tree_edgeEEEN10open_query12oqgraph_goalILb0ENS_18on_discover_vertexESM_EEEEENS_16two_bit_judy_mapINS1_25vertex_index_property_mapEEEEEvRKT_NS_12graph_traitsISY_E17vertex_descriptorERT0_T1_T2_+0x3e4)[0x7f407f9d2d74]
 
/usr/lib/mysql/plugin/ha_oqgraph.so(_ZN10open_query7oqgraph6searchEPiPyS2_+0xcde)[0x7f407f9cd33e]
 
/usr/lib/mysql/plugin/ha_oqgraph.so(_ZN10ha_oqgraph14index_read_idxEPhjPKhj16ha_rkey_function+0x36b)[0x7f407f9ca36b]
 
mysqld(_ZN7handler17ha_index_read_mapEPhPKhm16ha_rkey_function+0x14c)[0x7f408400aebc]
 
mysqld(+0x447fd3)[0x7f4083ed0fd3]
 
mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0x161)[0x7f4083ecdf11]
 
mysqld(+0x45c55d)[0x7f4083ee555d]
 
mysqld(_ZN4JOIN10exec_innerEv+0xa46)[0x7f4083ef87a6]
 
mysqld(_ZN4JOIN4execEv+0x11)[0x7f4083efa581]
 
mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x1dd)[0x7f4083ef71ed]
 
mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x28d)[0x7f4083efa8dd]
 
mysqld(+0x417561)[0x7f4083ea0561]
 
mysqld(_Z21mysql_execute_commandP3THD+0x4ba9)[0x7f4083eaabd9]
 
mysqld(+0x42379a)[0x7f4083eac79a]
 
mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x14df)[0x7f4083eadd5f]
 
mysqld(_Z24do_handle_one_connectionP3THD+0x47b)[0x7f4083f718fb]
 
mysqld(handle_one_connection+0x47)[0x7f4083f719d7]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50)[0x7f4083651b50]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f4081d5f0ed]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7f404bc1f020): is an invalid pointer
 
Connection ID (thread ID): 4
 
Status: NOT_KILLED
 
 
 
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
 
 
 
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.
 
 



 Comments   
Comment by Elena Stepanova [ 2014-06-17 ]

Reproduced using mysqlslap.
cat 1.sql

DROP DATABASE IF EXISTS test;
 
CREATE DATABASE test;
 
USE test;
 
CREATE TABLE oq_backing (origid INT UNSIGNED NOT NULL, destid INT UNSIGNED NOT NULL, PRIMARY KEY (origid, destid), KEY (destid));
 
INSERT INTO oq_backing(origid, destid) VALUES (1,2), (2,3), (3,4), (4,5), (2,6), (5,6);
 
CREATE TABLE oq_graph (latch VARCHAR(32) NULL, origid BIGINT UNSIGNED NULL, destid BIGINT UNSIGNED NULL, weight DOUBLE NULL, seq BIGINT UNSIGNED NULL, linkid BIGINT UNSIGNED NULL,  KEY (latch, origid, destid) USING HASH, KEY (latch, destid, origid) USING HASH) ENGINE=OQGRAPH data_table='oq_backing' origid='origid' destid='destid';
 

client/mysqlslap --query="SELECT * FROM oq_graph WHERE latch='breadth_first' AND origid=1 AND destid=6;" --port=3306 --protocol=tcp -uroot --create-schema=test --create=1.sql --concurrency=4 --number-of-queries=100

Assertion failure on a debug build:

mysqld: 10.0/sql/handler.cc:2417: THD* handler::ha_thd() const: Assertion `!table || !table->in_use || table->in_use == _current_thd()' failed.
 
140617  2:18:55 [ERROR] mysqld got signal 6 ;
 

#6  0x00007f066e61c621 in *__GI___assert_fail (assertion=0xfef5a8 "!table || !table->in_use || table->in_use == _current_thd()", file=<optimized out>, line=2417, function=0xff1f20 "THD* handler::ha_thd() const") at assert.c:81
 
#7  0x0000000000867238 in handler::ha_thd (this=0x7f0651c96088) at 10.0/sql/handler.cc:2417
 
#8  0x0000000000a0d627 in ha_innobase::extra (this=0x7f0651c96088, operation=HA_EXTRA_IS_ATTACHED_CHILDREN) at 10.0/storage/xtradb/handler/ha_innodb.cc:12810
 
#9  0x00007f06441c75e3 in ha_oqgraph::extra (this=0x7f0651c81088, operation=HA_EXTRA_IS_ATTACHED_CHILDREN) at 10.0/storage/oqgraph/ha_oqgraph.cc:1118
 
#10 0x00000000007f34af in tc_acquire_table (thd=0x7f06557ed070, share=0x7f065344f688) at 10.0/sql/table_cache.cc:342
 
#11 0x00000000007f4397 in tdc_acquire_share (thd=0x7f06557ed070, db=0x7f065344a8c8 "test", table_name=0x7f065344a2a8 "oq_graph", key=0x7f065344a729 "test", key_length=14, hash_value=3220223330, flags=3, out_table=0x7f06705553a8) at 10.0/sql/table_cache.cc:765
 
#12 0x00000000006172fd in open_table (thd=0x7f06557ed070, table_list=0x7f065344a2f0, mem_root=0x7f06705555d0, ot_ctx=0x7f0670555590) at 10.0/sql/sql_base.cc:2316
 
#13 0x0000000000619e37 in open_and_process_table (thd=0x7f06557ed070, lex=0x7f06557f0cb0, tables=0x7f065344a2f0, counter=0x7f06705556e4, flags=0, prelocking_strategy=0x7f0670555720, has_prelocking_list=false, ot_ctx=0x7f0670555590, new_frm_mem=0x7f06705555d0) at 10.0/sql/sql_base.cc:3917
 
#14 0x000000000061b019 in open_tables (thd=0x7f06557ed070, start=0x7f06705556a0, counter=0x7f06705556e4, flags=0, prelocking_strategy=0x7f0670555720) at 10.0/sql/sql_base.cc:4459
 
#15 0x000000000061bf22 in open_and_lock_tables (thd=0x7f06557ed070, tables=0x7f065344a2f0, derived=true, flags=0, prelocking_strategy=0x7f0670555720) at 10.0/sql/sql_base.cc:5076
 
#16 0x00000000006105bb in open_and_lock_tables (thd=0x7f06557ed070, tables=0x7f065344a2f0, derived=true, flags=0) at 10.0/sql/sql_base.h:485
 
#17 0x000000000067eeb8 in execute_sqlcom_select (thd=0x7f06557ed070, all_tables=0x7f065344a2f0) at 10.0/sql/sql_parse.cc:5208
 
#18 0x0000000000677544 in mysql_execute_command (thd=0x7f06557ed070) at 10.0/sql/sql_parse.cc:2554
 
#19 0x00000000006818d7 in mysql_parse (thd=0x7f06557ed070, rawbuf=0x7f065344a088 "SELECT * FROM oq_graph WHERE latch='breadth_first' AND origid=1 AND destid=6", length=76, parser_state=0x7f0670556660) at 10.0/sql/sql_parse.cc:6409
 
#20 0x00000000006747e5 in dispatch_command (command=COM_QUERY, thd=0x7f06557ed070, packet=0x7f06557f3071 "SELECT * FROM oq_graph WHERE latch='breadth_first' AND origid=1 AND destid=6;", packet_length=77) at 10.0/sql/sql_parse.cc:1309
 
#21 0x0000000000673b8a in do_command (thd=0x7f06557ed070) at 10.0/sql/sql_parse.cc:1006
 
#22 0x000000000078f4f1 in do_handle_one_connection (thd_arg=0x7f06557ed070) at 10.0/sql/sql_connect.cc:1379
 
#23 0x000000000078f244 in handle_one_connection (arg=0x7f06557ed070) at 10.0/sql/sql_connect.cc:1293
 
#24 0x00007f06701d3b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
 
#25 0x00007f066e6cba7d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

Assertion failure on a release build:

2014-06-17 02:31:57 7ff78b9a3700  InnoDB: Assertion failure in thread 140701175789312 in file ha_innodb.cc line 9254
 
InnoDB: Failing assertion: prebuilt->trx == thd_to_trx(ha_thd())
 

#1  0x00007ff789a726f0 in *__GI_abort () at abort.c:92
 
#2  0x0000000000821cea in ha_innobase::position (this=0x7ff75fc69020, record=0x7ff75fc48820 "\377\001") at 10.0.12/storage/xtradb/handler/ha_innodb.cc:9254
 
#3  0x00007ff761df5793 in oqgraph3::cursor::record_position (this=0x7ff7614ba1a0) at 10.0.12/storage/oqgraph/oqgraph_thunk.cc:106
 
#4  0x00007ff761df5823 in oqgraph3::cursor_ptr::operator!= (this=<optimized out>, x=...) at 10.0.12/storage/oqgraph/oqgraph_thunk.cc:65
 
#5  0x00007ff761df00e5 in operator!= (x=..., this=0x7ff78b99f520) at 10.0.12/storage/oqgraph/oqgraph_shim.h:143
 
#6  boost::breadth_first_visit<oqgraph3::graph, boost::queue<unsigned long long, std::deque<unsigned long long, std::allocator<unsigned long long> > >, boost::bfs_visitor<std::pair<boost::predecessor_recorder<boost::associative_property_map<boost::unordered::unordered_map<unsigned long long, unsigned long long, boost::hash<unsigned long long>, std::equal_to<unsigned long long>, std::allocator<std::pair<unsigned long long const, unsigned long long> > > >, boost::on_tree_edge>, open_query::oqgraph_goal<false, boost::on_discover_vertex, boost::associative_property_map<boost::unordered::unordered_map<unsigned long long, unsigned long long, boost::hash<unsigned long long>, std::equal_to<unsigned long long>, std::allocator<std::pair<unsigned long long const, unsigned long long> > > > > > >, boost::two_bit_judy_map<oqgraph3::vertex_index_property_map> > (g=..., s=1, Q=..., vis=..., color=...) at /usr/include/boost/graph/breadth_first_search.hpp:77
 
#7  0x00007ff761deaff2 in open_query::oqgraph::search (this=0x7ff75fc77080, latch=<optimized out>, orig_id=<optimized out>, dest_id=0x7ff78b99faf8) at 10.0.12/storage/oqgraph/graphcore.cc:820
 
#8  0x00007ff761de809a in ha_oqgraph::index_read_idx (this=0x7ff75fc45020, buf=0x7ff75fc47420 "\370\rbreadth_first", index=<optimized out>, key=<optimized out>, key_len=<optimized out>, find_flag=<optimized out>) at 10.0.12/storage/oqgraph/ha_oqgraph.cc:966
 
#9  0x000000000070673c in handler::ha_index_read_map (this=0x7ff75fc45020, buf=0x7ff75fc47420 "\370\rbreadth_first", key=0x7ff7614daa38 "", keypart_map=7, find_flag=HA_READ_KEY_EXACT) at 10.0.12/sql/handler.cc:2585
 
#10 0x0000000000609e3f in join_read_always_key (tab=0x7ff7614da6f0) at 10.0.12/sql/sql_select.cc:18334
 
#11 0x00000000005fd7c1 in sub_select (join=0x7ff7614203d0, join_tab=0x7ff7614da6f0, end_of_records=<optimized out>) at 10.0.12/sql/sql_select.cc:17589
 
#12 0x000000000060903d in do_select (join=join@entry=0x7ff7614203d0, fields=fields@entry=0x7ff770a153d8, table=table@entry=0x0, procedure=0x0) at 10.0.12/sql/sql_select.cc:17254
 
#13 0x0000000000619a92 in JOIN::exec_inner (this=this@entry=0x7ff7614203d0) at 10.0.12/sql/sql_select.cc:3076
 
#14 0x000000000061b629 in JOIN::exec (this=0x7ff7614203d0) at 10.0.12/sql/sql_select.cc:2366
 
#15 0x0000000000618618 in mysql_select (thd=thd@entry=0x7ff770a11008, rref_pointer_array=rref_pointer_array@entry=0x7ff770a15538, tables=0x7ff76141f288, wild_num=<optimized out>, fields=..., conds=<optimized out>, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=result@entry=0x7ff7614203b0, unit=unit@entry=0x7ff770a14bd8, select_lex=select_lex@entry=0x7ff770a152c0) at 10.0.12/sql/sql_select.cc:3303
 
#16 0x000000000061b924 in handle_select (thd=0x7ff770a11008, lex=0x7ff770a14b10, result=0x7ff7614203b0, setup_tables_done_option=0) at 10.0.12/sql/sql_select.cc:372
 
#17 0x00000000005cb7bb in execute_sqlcom_select (thd=thd@entry=0x7ff770a11008, all_tables=0x7ff76141f288) at 10.0.12/sql/sql_parse.cc:5263
 
#18 0x00000000005d6488 in mysql_execute_command (thd=thd@entry=0x7ff770a11008) at 10.0.12/sql/sql_parse.cc:2554
 
#19 0x00000000005d8c6c in mysql_parse (parser_state=0x7ff78b9a2160, thd=0x7ff770a11008, rawbuf=<optimized out>, length=<optimized out>) at 10.0.12/sql/sql_parse.cc:6409
 
#20 mysql_parse (thd=0x7ff770a11008, rawbuf=<optimized out>, length=76, parser_state=0x7ff78b9a2160) at 10.0.12/sql/sql_parse.cc:6330
 
#21 0x00000000005da335 in dispatch_command (command=COM_QUERY, thd=0x7ff770a11008, packet=<optimized out>, packet_length=<optimized out>) at 10.0.12/sql/sql_parse.cc:1309
 
#22 0x00000000006819bd in do_handle_one_connection (thd_arg=thd_arg@entry=0x7ff770a11008) at 10.0.12/sql/sql_connect.cc:1379
 
#23 0x0000000000681a80 in handle_one_connection (arg=0x7ff770a11008) at 10.0.12/sql/sql_connect.cc:1293
 
#24 0x00007ff78b61fb50 in start_thread (arg=<optimized out>) at pthread_create.c:304
 
#25 0x00007ff789b17a7d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

Comment by Andrew McDonnell [ 2014-10-24 ]

elenst is it possible to do something like mysqlslap from mysql-test-run ?

Comment by Andrew McDonnell [ 2014-10-24 ]

I just discovered `-parallel` option, does the trick

Comment by Andrew McDonnell [ 2014-10-30 ]

Can you please try testing this building MariaDB using the branch:

https://github.com/pastcompute/server/tree/oqgraph_mdev_6282_6345_5748

git clone https://github.com/pastcompute/server.git
 
git checkout oqgraph_mdev_6282_6345_5748
 
... build and test as normal ...

Comment by Andrew McDonnell [ 2015-02-27 ]

I just rebased my work on latest 10.1 and intending to submit pull request after re-testing

Comment by Andrew McDonnell [ 2015-02-27 ]

10.1 version pull request: https://github.com/MariaDB/server/pull/16

I'll be trying to get 10.0 sorted soon

Comment by Andrew McDonnell [ 2015-02-28 ]

https://github.com/MariaDB/server/pull/17

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