[MDEV-9305] MariaDB Server Crashes while querying OQGRAPH. This happens when using connection pooling from an node.js application. Created: 2015-12-18  Updated: 2022-09-08

Status: Confirmed
Project: MariaDB Server
Component/s: Storage Engine - OQGRAPH
Affects Version/s: 10.1.8, 10.0, 10.1
Fix Version/s: 10.1

Type: Bug Priority: Major
Reporter: Ben Chege Ngumi Assignee: Andrew McDonnell
Resolution: Unresolved Votes: 1
Labels: None
Environment:

Distributor ID: Ubuntu
Description: Ubuntu 15.10
Release: 15.10
Codename: wily
Linux 4.2.0-17-generic
running on the Azure Cloud

Attachments: PNG File capture-for-jira-screenshot-20151218-201217-130.png    

 Description    

Dec 18 14:09:27 spotlight mysqld[8755]: 2015-12-18 14:09:27 140541720311552 [Warning] Aborted connection 176 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 14:09:27 spotlight mysqld[8755]: 2015-12-18 14:09:27 140541766850304 [Warning] Aborted connection 175 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 14:09:27 spotlight mysqld[8755]: 2015-12-18 14:09:27 140541766551296 [Warning] Aborted connection 156 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 14:13:21 spotlight systemd[1]: Started Session 87 of user spotlightadmin.
 
Dec 18 14:14:05 spotlight mysqld[8755]: 2015-12-18 14:14:05 140541720012544 [Warning] Aborted connection 177 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 14:14:05 spotlight mysqld[8755]: 2015-12-18 14:14:05 140541766551296 [Warning] Aborted connection 193 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 14:14:05 spotlight mysqld[8755]: 2015-12-18 14:14:05 140541719713536 [Warning] Aborted connection 194 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 14:17:01 spotlight CRON[9261]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
 
Dec 18 14:24:19 spotlight mysqld[8755]: 2015-12-18 14:24:19 140541766850304 [Warning] Aborted connection 195 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 14:27:23 spotlight mysqld[8755]: 2015-12-18 14:27:23 140541719713536 [Warning] Aborted connection 205 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 14:57:31 spotlight systemd[1]: Started Session 89 of user spotlightadmin.
 
Dec 18 14:59:11 spotlight systemd[1]: Started Session 90 of user spotlightadmin.
 
Dec 18 15:00:22 spotlight mysqld[8755]: 2015-12-18 15:00:22 140541719713536 [Warning] Aborted connection 378 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:00:22 spotlight mysqld[8755]: 2015-12-18 15:00:22 140541720610560 [Warning] Aborted connection 379 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:09:13 spotlight systemd[1]: Started Session 91 of user spotlightadmin.
 
Dec 18 15:10:39 spotlight mysqld[8755]: 2015-12-18 15:10:39 140541720012544 [Warning] Aborted connection 380 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:11:40 spotlight mysqld[8755]: 2015-12-18 15:11:40 140541720012544 [Warning] Aborted connection 426 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:11:40 spotlight mysqld[8755]: 2015-12-18 15:11:40 140541766850304 [Warning] Aborted connection 427 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:11:40 spotlight mysqld[8755]: 2015-12-18 15:11:40 140541719713536 [Warning] Aborted connection 401 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:17:01 spotlight CRON[9644]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
 
Dec 18 15:21:41 spotlight mysqld[8755]: 2015-12-18 15:21:41 140541766551296 [Warning] Aborted connection 428 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:33:50 spotlight systemd[1]: Started Session 93 of user spotlightadmin.
 
Dec 18 15:34:15 spotlight systemd[1]: Started Session 94 of user spotlightadmin.
 
Dec 18 15:34:29 spotlight mysqld[8755]: 2015-12-18 15:34:29 140541720012544 [Warning] Aborted connection 520 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:34:29 spotlight mysqld[8755]: 2015-12-18 15:34:29 140541766551296 [Warning] Aborted connection 521 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:35:29 spotlight mysqld[8755]: 2015-12-18 15:35:29 140541720311552 [Warning] Aborted connection 528 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:35:29 spotlight mysqld[8755]: 2015-12-18 15:35:29 140541720012544 [Warning] Aborted connection 526 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:35:29 spotlight mysqld[8755]: 2015-12-18 15:35:29 140541766850304 [Warning] Aborted connection 522 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:35:29 spotlight mysqld[8755]: 2015-12-18 15:35:29 140541766551296 [Warning] Aborted connection 527 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:37:12 spotlight systemd[1]: Started Session 95 of user spotlightadmin.
 
Dec 18 15:42:24 spotlight mysqld[8755]: 2015-12-18 15:42:24 140541766551296 [Warning] Aborted connection 557 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:42:24 spotlight mysqld[8755]: 2015-12-18 15:42:24 140541719713536 [Warning] Aborted connection 529 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:42:24 spotlight mysqld[8755]: 2015-12-18 15:42:24 140541720610560 [Warning] Aborted connection 558 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 15:50:39 spotlight mysqld[8755]: 2015-12-18 15:50:39 140541720610560 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave. Statement: update contacts as c  inner join subject_numbers n on n.telephonenumber=c.phonenumber inner join subject_matters sm on sm.uniqueid = n.subject_matter_uniqueid set c.subject_matter_user_id=sm.uniqueid and c.updateSequenceNumber=328 where c.user_id='10205587125490229' and c.updateSequenceNumber=327
 
Dec 18 15:50:39 spotlight mysqld[8755]: 2015-12-18 15:50:39 140541720610560 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave. Statement: update contacts as c  inner join user u on c.phonenumber=u.mobileno set c.other_user_id=u.uniqueid and c.updateSequenceNumber=328 where c.user_id='10205587125490229'
 
Dec 18 15:52:26 spotlight mysqld[8755]: 2015-12-18 15:52:26 140541720012544 [Warning] Aborted connection 559 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 16:00:39 spotlight mysqld[8755]: 2015-12-18 16:00:39 140541720610560 [Warning] Aborted connection 569 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 16:14:50 spotlight mysqld[8755]: 2015-12-18 16:14:50 140541720311552 [Warning] Aborted connection 644 to db: 'jalise_dev' user: 'root' host: 'localhost' (Unknown error)
 
Dec 18 16:17:01 spotlight CRON[9941]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
 

Dec 18 16:19:20 spotlight mysqld[8755]: 151218 16:19:20 [ERROR] mysqld got signal 11 ;
 
Dec 18 16:19:20 spotlight mysqld[8755]: This could be because you hit a bug. It is also possible that this binary
 
Dec 18 16:19:20 spotlight mysqld[8755]: or one of the libraries it was linked against is corrupt, improperly built,
 
Dec 18 16:19:20 spotlight mysqld[8755]: or misconfigured. This error can also be caused by malfunctioning hardware.
 
Dec 18 16:19:20 spotlight mysqld[8755]: To report this bug, see http://kb.askmonty.org/en/reporting-bugs
 
Dec 18 16:19:20 spotlight mysqld[8755]: We will try our best to scrape up some info that will hopefully help
 
Dec 18 16:19:20 spotlight mysqld[8755]: diagnose the problem, but since we have already crashed,
 
Dec 18 16:19:20 spotlight mysqld[8755]: something is definitely wrong and this may fail.
 
Dec 18 16:19:20 spotlight mysqld[8755]: Server version: 10.1.8-MariaDB-1~vivid-log
 
Dec 18 16:19:20 spotlight mysqld[8755]: key_buffer_size=134217728
 
Dec 18 16:19:20 spotlight mysqld[8755]: read_buffer_size=2097152
 
Dec 18 16:19:20 spotlight mysqld[8755]: max_used_connections=6
 
Dec 18 16:19:20 spotlight mysqld[8755]: max_threads=102
 
Dec 18 16:19:20 spotlight mysqld[8755]: thread_count=3
 
Dec 18 16:19:20 spotlight mysqld[8755]: It is possible that mysqld could use up to
 
Dec 18 16:19:20 spotlight mysqld[8755]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 759822 K  bytes of memory
 
Dec 18 16:19:20 spotlight mysqld[8755]: Hope that's ok; if not, decrease some variables in the equation.
 
Dec 18 16:19:20 spotlight mysqld[8755]: Thread pointer: 0x0x7fd233942008
 
Dec 18 16:19:20 spotlight mysqld[8755]: Attempting backtrace. You can use the following information to find out
 
Dec 18 16:19:20 spotlight mysqld[8755]: where mysqld died. If you see no messages after this, something went
 
Dec 18 16:19:20 spotlight mysqld[8755]: terribly wrong...
 
Dec 18 16:19:20 spotlight mysqld[8755]: stack_bottom = 0x7fd26b478db8 thread_stack 0x48000
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x5651419fae2e]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(handle_fatal_signal+0x34d)[0x56514153ea3d]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /lib/x86_64-linux-gnu/libpthread.so.0(+0x10d10)[0x7fd26caefd10]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(+0x71f91d)[0x5651416c791d]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(_Z11open_tablesP3THDRK14DDL_options_stPP10TABLE_LISTPjjP19Prelocking_strategy+0xfb0)[0x56514137b140]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(_Z20open_and_lock_tablesP3THDRK14DDL_options_stP10TABLE_LISTbjP19Prelocking_strategy+0x33)[0x56514137b563]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(+0x40a86d)[0x5651413b286d]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x5d41)[0x5651413be611]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x20e)[0x5651413c193e]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1c89)[0x5651413c43f9]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(_Z10do_commandP3THD+0x16e)[0x5651413c4b3e]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x182)[0x56514148c3e2]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /usr/sbin/mysqld(handle_one_connection+0x40)[0x56514148c5a0]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76aa)[0x7fd26cae66aa]
 
Dec 18 16:19:20 spotlight mysqld[8755]: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fd26c191eed]
 
Dec 18 16:19:20 spotlight mysqld[8755]: Trying to get some variables.
 
Dec 18 16:19:20 spotlight mysqld[8755]: Some pointers may be invalid and cause the dump to abort.
 
Dec 18 16:19:20 spotlight mysqld[8755]: Query (0x7fd23a6f9020): select  uu.*, fn_distance_to_current_user(1,uu.id) distance_to_current_user, fn_path_to_current_user(1,uu.id) path_to_current_user, fn_known_by_how_many_users(uu.id) know_to_how_many_others,fn_knows_how_many_users(uu.id) knows_how_many_users  from  (select distinct u.* from user u   where u.systemaccount=1 and u.updateSequenceNumber > 0 union  select distinct u.* from user u   inner join contacts c on u.mobileNo=c.phonenumber  where c.user_id='10205587125490229' and u.updateSequenceNumber > 0 union   select distinct  u.* from user u   inner join reviews r on r.created_by_user_id=u.uniqueID  inner join subject_numbers s on r.subject_matter_uniqueid= s.subject_matter_uniqueid  inner join contacts c on s.telephonenumber = c.phonenumber  where c.user_id='10205587125490229' and u.updateSequenceNumber > 0 union   select distinct u.* from user u   inner join likes l on l.created_by_user_id=u.uniqueID  inner join reviews r on l.review_uniqueid=r.uniqueID  inner join subject_numbers s on r.subject_matter_uniqueid= s.subject_matter_uniqueid  inner join contacts c on s.telephonenumber = c.phonenumber  where c.user_id='10205587125490229'  and u.updateSequenceNumber > 0 union   select distinct u.* from user u   inner join comments cn on cn.created_by_user_id=u.uniqueID  inner join reviews r on cn.review_uniqueid=r.uniqueID  inner join subject_numbers s on r.subject_matter_uniqueid= s.subject_matter_uniqueid  inner join contacts c on s.telephonenumber=c.phonenumber   where c.user_id='10205587125490229' and u.updateSequenceNumber > 0 union   select distinct u.* from user u   inner join call_logs c on u.mobileNo=c.number   where c.user_id='10205587125490229'  and u.updateSequenceNumber > 0 union   select distinct  u.* from user u   inner join reviews r on r.created_by_user_id=u.uniqueID  inner join subject_numbers s on r.subject_matter_uniqueid= s.subject_matter_uniqueid  inner join call_logs c on s.telephonenumber = c.number  where c.user_id='10205587125490229'  and u.updateSequenceNumber > 0 union  sele
 
Dec 18 16:19:20 spotlight mysqld[8755]: ct distinct u.* from user u   inner join likes l on l.created_by_user_id=u.uniqueID  inner join reviews r on l.review_uniqueid=r.uniqueID  inner join subject_numbers s on r.subject_matter_uniqueid= s.subject_matter_uniqueid  inner join call_logs c on s.telephonenumber = c.number  where c.user_id='10205587125490229'  and u.updateSequenceNumber > 0 union   select distinct u.* from user u   inner join comments cn on cn.created_by_user_id=u.uniqueID  inner join reviews r on cn.review_uniqueid=r.uniqueID  inner join subject_numbers s on r.subject_matter_uniqueid= s.subject_matter_uniqueid  inner join call_logs c on s.telephonenumber=c.number   where c.user_id='10205587125490229'  and u.updateSequenceNumber > 0 ) uu
 
Dec 18 16:19:20 spotlight mysqld[8755]: Connection ID (thread ID): 701
 
Dec 18 16:19:20 spotlight mysqld[8755]: Status: NOT_KILLED
 
Dec 18 16:19:20 spotlight mysqld[8755]: 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
 
Dec 18 16:19:20 spotlight mysqld[8755]: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
Dec 18 16:19:20 spotlight mysqld[8755]: information that should help you find out what is causing the crash.
 
Dec 18 16:19:20 spotlight systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
 
Dec 18 16:19:20 spotlight systemd[1]: mariadb.service: Unit entered failed state.
 
Dec 18 16:19:20 spotlight systemd[1]: mariadb.service: Failed with result 'exit-code'.



 Comments   
Comment by Elena Stepanova [ 2015-12-29 ]

masukuma,

Does the crash always happen on the same query?
Would you, by any chance, be able to provide a data dump for the involved tables? If you can, please upload it to ftp.askmonty.org/private, only MariaDB developers will have access to it.
If not, please at least paste or upload the output of SHOW CREATE TABLE .. }} and {{SHOW INDEX IN ... for all tables participating in the query.
I found references to these ones, but I could have missed something:

user
 
contacts
 
reviews
 
subject_numbers
 
likes
 
comments
 
call_logs

Please also attach your cnf file(s).

Thanks.

Comment by Ben Chege Ngumi [ 2015-12-29 ]

Yes - the crash is always after that query is run but not that the query crashes the service. i.e. I have attached the syslog log that has the crash information. all the files are stored as 'mariadb-bug-masukuma-bug.tgz' and the conf files as 'mariadb-bug-masukuma-bug-cnf.tgz'

Thanks!

Comment by Elena Stepanova [ 2016-01-08 ]

masukuma,

Thanks for the data.
Apart from tables, there are also 4 functions involved into the query, they are missing from the provided data dump:

fn_distance_to_current_user
 
fn_path_to_current_user
 
fn_known_by_how_many_users
 
fn_knows_how_many_users

Also, all cnf files in mariadb-bug-masukuma-bug-cnf.tgz are empty, their contents is commented. But you cannot be running on default settings only, at the very least you have binary log enabled, according to your logs. Could you please find and send missing cnf file(s)? If you don't know where they are, please paste or upload the output of SHOW GLOBAL VARIABLES command.

Thanks.

Comment by richardeaxon [ 2016-01-19 ]

I get a similar crash using OQGRAPH using the official MariaDB 10.0.23 RPM's on Centos 7. The crashes do not occur on every query but over time. Sometimes I can do many 100's of queries, sometimes one or two will cause a crash. I use various queries, but have been able to capture this one. Some of my tables contain foreign keys which I removed as a test. This did not help. Some of my queries contain unions too.

12 Connect root@localhost as anonymous on xxxxx
12 Query SELECT * FROM group_ports WHERE port_guid='3dac1465-a618-11e5-8842-bc305bdfaf9f'
12 Query SELECT routing.origid,t1.node_name, routing.linkid,t2.node_name,t2.node_descrip,
node_types.node_type_name,node_types.script_provision_definition,routing.seq,routing.weight
FROM routing
join `nodes` `t1` on `routing`.`origid` = `t1`.`node_id`
join `nodes` `t2` on `routing`.`linkid` = `t2`.`node_id`
join `node_types` on `t2`.`node_type_id` = `node_types`.`node_type_id`
WHERE latch='dijkstra' AND origid=40
ORDER BY seq
/usr/sbin/mysqld, Version: 10.0.23-MariaDB-log (MariaDB Server). started with:
Tcp port: 0 Unix socket: (null)
Time Id Command Argument

160119 3:14:31 [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 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.23-MariaDB-log
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=4
max_threads=153
thread_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467003 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x7f671ec21008
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 = 0x7f673a890d80 thread_stack 0x48000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0xbd0aae]
/usr/sbin/mysqld(handle_fatal_signal+0x390)[0x73aa40]
/lib64/libpthread.so.0(+0xf100)[0x7f673a4e1100]
/usr/sbin/mysqld[0x8b78ff]
/usr/sbin/mysqld(_Z11open_tablesP3THDPP10TABLE_LISTPjjP19Prelocking_strategy+0x9e5)[0x58e7d5]
/usr/sbin/mysqld(_Z20open_and_lock_tablesP3THDP10TABLE_LISTbjP19Prelocking_strategy+0x34)[0x58f2d4]
/usr/sbin/mysqld[0x5c797f]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x527f)[0x5d6aff]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x1f9)[0x5d9809]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x17f5)[0x5db585]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x22b)[0x6a2beb]
/usr/sbin/mysqld(handle_one_connection+0x39)[0x6a2ca9]
/lib64/libpthread.so.0(+0x7dc5)[0x7f673a4d9dc5]
/lib64/libc.so.6(clone+0x6d)[0x7f6738d5621d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f671ed93020): is an invalid pointer
Connection ID (thread ID): 12
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.
160119 03:14:31 mysqld_safe Number of processes running now: 0
160119 03:14:31 mysqld_safe mysqld restarted
160119 3:14:31 [Note] /usr/sbin/mysqld (mysqld 10.0.23-MariaDB-log) starting as process 18010 ...
160119 3:14:31 [Note] InnoDB: Using mutexes to ref count buffer pool pages
160119 3:14:31 [Note] InnoDB: The InnoDB memory heap is disabled
160119 3:14:31 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
160119 3:14:31 [Note] InnoDB: Memory barrier is not used
160119 3:14:31 [Note] InnoDB: Compressed tables use zlib 1.2.7
160119 3:14:31 [Note] InnoDB: Using Linux native AIO
160119 3:14:31 [Note] InnoDB: Using CPU crc32 instructions
160119 3:14:31 [Note] InnoDB: Initializing buffer pool, size = 128.0M
160119 3:14:31 [Note] InnoDB: Completed initialization of buffer pool
160119 3:14:31 [Note] InnoDB: Highest supported file format is Barracuda.
160119 3:14:31 [Note] InnoDB: The log sequence numbers 58756995 and 58756995 in ibdata files do not match the log sequence number 58956861 in the ib_logfiles!
160119 3:14:31 [Note] InnoDB: Database was not shutdown normally!
160119 3:14:31 [Note] InnoDB: Starting crash recovery.
160119 3:14:31 [Note] InnoDB: Reading tablespace information from the .ibd files...
160119 3:14:31 [Note] InnoDB: Restoring possible half-written data pages
160119 3:14:31 [Note] InnoDB: from the doublewrite buffer...
160119 3:14:31 [Note] InnoDB: 128 rollback segment(s) are active.
160119 3:14:31 [Note] InnoDB: Waiting for purge to start
160119 3:14:31 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.26-76.0 started; log sequence number 58956861
160119 3:14:31 [Note] Plugin 'FEEDBACK' is disabled.
160119 3:14:31 [Note] Recovering after a crash using tc.log
160119 3:14:31 [Note] Starting crash recovery...
160119 3:14:31 [Note] Crash recovery finished.
160119 3:14:31 [Note] Server socket created on IP: '::'.
160119 3:14:31 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.0.23-MariaDB-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 MariaDB Server

Comment by richardeaxon [ 2016-01-21 ]

I have uploaded a repeatable test case to reproduce the crash. Uploaded to ftp.askmonty.org/private as oqgraph_crash.tgz.

Create a database called oqgraph_stress and source the schema.sql into the database. Then run stress.sh a couple of times to create the crash. If you want to immediately create the crash, run stress.sh in two sessions concurrently.

As mentioned this is reproducible on Mariadb 10.0.23 supplied stock RPM's.

Comment by Elena Stepanova [ 2016-01-21 ]

Ellerbrockr, thanks a lot for the test case.
Reproducible for me also.

Release version produces a crash, debug version assertion failure.

Stack trace from 10.0 commit 74b1af19e9270a932f9e5f907eff53852984a7d3

 
mysqld: /src/10.0/sql/handler.cc:2473: THD* handler::ha_thd() const: Assertion `!table || !table->in_use || table->in_use == _current_thd()' failed.
 
160121 15:24:47 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f48705131d2 in __assert_fail () from /lib64/libc.so.6
 
#8  0x000000000085fefa in handler::ha_thd (this=0x7f4849510088) at /src/10.0/sql/handler.cc:2473
 
#9  0x0000000000a0fea9 in ha_innobase::extra (this=0x7f4849510088, operation=HA_EXTRA_IS_ATTACHED_CHILDREN) at /src/10.0/storage/xtradb/handler/ha_innodb.cc:13104
 
#10 0x00007f48485cb5c3 in ha_oqgraph::extra (this=0x7f4849567888, operation=HA_EXTRA_IS_ATTACHED_CHILDREN) at /src/10.0/storage/oqgraph/ha_oqgraph.cc:1102
 
#11 0x00000000007eccd6 in tc_acquire_table (thd=0x7f4849495f30, share=0x7f4849444288) at /src/10.0/sql/table_cache.cc:342
 
#12 0x00000000007edbc5 in tdc_acquire_share (thd=0x7f4849495f30, db=0x7f4849583998 "oqgraph_stress", table_name=0x7f4849583380 "routing", key=0x7f48495837f9 "oqgraph_stress", key_length=23, hash_value=3134965533, flags=3, out_table=0x7f48725a5438) at /src/10.0/sql/table_cache.cc:765
 
#13 0x000000000060c03c in open_table (thd=0x7f4849495f30, table_list=0x7f48495833b8, mem_root=0x7f48725a5640, ot_ctx=0x7f48725a5600) at /src/10.0/sql/sql_base.cc:2379
 
#14 0x000000000060ec65 in open_and_process_table (thd=0x7f4849495f30, lex=0x7f48494997d8, tables=0x7f48495833b8, counter=0x7f48725a5744, flags=0, prelocking_strategy=0x7f48725a5780, has_prelocking_list=false, ot_ctx=0x7f48725a5600, new_frm_mem=0x7f48725a5640) at /src/10.0/sql/sql_base.cc:4040
 
#15 0x000000000060fd2a in open_tables (thd=0x7f4849495f30, start=0x7f48725a5700, counter=0x7f48725a5744, flags=0, prelocking_strategy=0x7f48725a5780) at /src/10.0/sql/sql_base.cc:4574
 
#16 0x0000000000610d16 in open_and_lock_tables (thd=0x7f4849495f30, tables=0x7f48495833b8, derived=true, flags=0, prelocking_strategy=0x7f48725a5780) at /src/10.0/sql/sql_base.cc:5217
 
#17 0x000000000060514b in open_and_lock_tables (thd=0x7f4849495f30, tables=0x7f48495833b8, derived=true, flags=0) at /src/10.0/sql/sql_base.h:489
 
#18 0x00000000006743de in execute_sqlcom_select (thd=0x7f4849495f30, all_tables=0x7f48495833b8) at /src/10.0/sql/sql_parse.cc:5249
 
#19 0x000000000066ca55 in mysql_execute_command (thd=0x7f4849495f30) at /src/10.0/sql/sql_parse.cc:2562
 
#20 0x00000000006771f3 in mysql_parse (thd=0x7f4849495f30, rawbuf=0x7f4849582088 "SELECT routing.origid,t1.node_name, routing.linkid,t2.node_name,t2.node_descrip,\n", ' ' <repeats 12 times>, "node_types.node_type_name,node_types.script_provision_definition,routing.seq,routing.weight\n", ' ' <repeats 12 times>, "FRO"..., length=993, parser_state=0x7f48725a66a0) at /src/10.0/sql/sql_parse.cc:6565
 
#21 0x0000000000669cbf in dispatch_command (command=COM_QUERY, thd=0x7f4849495f30, packet=0x7f484950a571 "SELECT routing.origid,t1.node_name, routing.linkid,t2.node_name,t2.node_descrip,\n", ' ' <repeats 12 times>, "node_types.node_type_name,node_types.script_provision_definition,routing.seq,routing.weight\n", ' ' <repeats 12 times>, "FRO"..., packet_length=993) at /src/10.0/sql/sql_parse.cc:1308
 
#22 0x0000000000668f8c in do_command (thd=0x7f4849495f30) at /src/10.0/sql/sql_parse.cc:998
 
#23 0x00000000007872c5 in do_handle_one_connection (thd_arg=0x7f4849495f30) at /src/10.0/sql/sql_connect.cc:1377
 
#24 0x0000000000787037 in handle_one_connection (arg=0x7f4849495f30) at /src/10.0/sql/sql_connect.cc:1292
 
#25 0x00007f48722360a4 in start_thread () from /lib64/libpthread.so.0

Comment by Andrew McDonnell [ 2016-01-22 ]

Hi, elenst are you still able to reproduce this again after applying https://github.com/MariaDB/server/pull/152 ?

Comment by Elena Stepanova [ 2016-01-22 ]

andymc73, I didn't try. If you are able to reproduce it easily before the patch, but not after the patch, then I suppose you can treat it as a duplicate, or better put it aside and close it together with MDEV-8206 when the patches are in the main tree.

Comment by richardeaxon [ 2016-01-25 ]

Hi,

This issue is quite important for me. I see that MDEV-8206 is over six months old and has not made it into the main branch. if MDEV-8206 is the solution, when will it get into an official MariaDB build release? I am not in a position to build from sources and would prefer to have an official MariaDB release before I invest time in trying to build from source.

Thanks.

Comment by richardeaxon [ 2016-01-26 ]

Building 10.0.23 from sources after applying MDEV-8206 resolves the issue in this case. I can run my stress test in multiple sessions without crashing.

Comment by Andrew McDonnell [ 2016-04-09 ]

There is an updated pull request for MDEV-8206

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