[MDEV-10363] Randomly Crashes with Higher Load Created: 2016-07-12  Updated: 2016-10-12  Resolved: 2016-10-12

Status: Closed
Project: MariaDB Server
Component/s: Locking
Affects Version/s: 10.0.24
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Fenero Support Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: need_feedback
Environment:

CentOS release 6.7 (Final)

Linux version 2.6.32-573.26.1.el6.x86_64 (mockbuild@c6b8.bsys.dev.centos.org) (gcc version 4.4.7 20120313 (Red Hat 4.4.7-16) (GCC) ) #1 SMP Wed May 4 00:57:44 UTC 2016


 Description   

Server randomly crashes throughout the day. Snippet of error log and GBD trace to follow:

60708 23:00:57 [ERROR] mysqld: Deadlock found when trying to get lock; try restarting transaction
 
160711 15:05:06 [ERROR] mysqld: Deadlock found when trying to get lock; try restarting transaction
 
160711 18:16:09 [ERROR] mysqld: Deadlock found when trying to get lock; try restarting transaction
 
160711 18:20:54 [ERROR] mysqld: Deadlock found when trying to get lock; try restarting transaction
 
pure virtual method called
 
pure virtual method called
 
pure virtual method called
 
terminate called recursively
 
terminate called recursively
 
160711 18:31:33 [ERROR] mysqld got signal 6 ;
 
pure virtual method called
 
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
 
 
 
terminate called recursively
 
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.24-MariaDB
 
key_buffer_size=6442450944
 
read_buffer_size=2097152
 
max_used_connections=2896
 
terminate called without an active exception
 
max_threads=5002
 
thread_count=2689
 
It is possible that mysqld could use up to
 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 26878534 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0x7fd272753008
 
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...
 
pure virtual method called
 
terminate called recursively
 
160711 18:32:41 mysqld_safe Number of processes running now: 0
 
160711 18:32:41 mysqld_safe mysqld restarted

BT

Thread debugging using libthread_db enabled]
 
Core was generated by `/usr/sbin/mysqld --basedir=/usr --datadir=/mnt/db_data/mysql --plugin-dir=/usr/'.
 
Program terminated with signal 6, Aborted.
 
#0  0x00007fdebe180625 in raise () from /lib64/libc.so.6
 
#0  0x00007fdebe180625 in raise () from /lib64/libc.so.6
 
No symbol table info available.
 
#1  0x00007fdebe181e05 in abort () from /lib64/libc.so.6
 
No symbol table info available.
 
#2  0x00007fdebe824991 in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib64/libstdc++.so.6
 
No symbol table info available.
 
#3  0x00007fdebe822bd6 in ?? () from /usr/lib64/libstdc++.so.6
 
No symbol table info available.
 
#4  0x00007fdebe822c03 in std::terminate() () from /usr/lib64/libstdc++.so.6
 
No symbol table info available.
 
#5  0x00007fdebe82355f in __cxa_pure_virtual () from /usr/lib64/libstdc++.so.6
 
No symbol table info available.
 
#6  0x00000000006ae6a2 in MDL_lock::can_grant_lock(enum_mdl_type, MDL_context*, bool) const ()
 
No symbol table info available.
 
#7  0x00000000006aedc2 in MDL_context::try_acquire_lock_impl(MDL_request*, MDL_ticket**) ()
 
No symbol table info available.
 
#8  0x00000000006af487 in MDL_context::acquire_lock(MDL_request*, unsigned long) ()
 
No symbol table info available.
 
#9  0x0000000000599966 in open_table_get_mdl_lock(THD*, Open_table_context*, MDL_request*, unsigned int, MDL_ticket**) ()
 
No symbol table info available.
 
#10 0x00000000005a0dfc in open_table(THD*, TABLE_LIST*, st_mem_root*, Open_table_context*) ()
 
No symbol table info available.
 
#11 0x00000000005a28a7 in open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) ()
 
No symbol table info available.
 
#12 0x00000000005a2b04 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) ()
 
No symbol table info available.
 
#13 0x00000000005d83b8 in execute_sqlcom_select(THD*, TABLE_LIST*) ()
 
No symbol table info available.
 
#14 0x00000000005e3a70 in mysql_execute_command(THD*) ()
 
No symbol table info available.
 
#15 0x00000000005e54e7 in mysql_parse ()
 
No symbol table info available.
 
#16 0x00000000005e795d in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
 
No symbol table info available.
 
#17 0x00000000006a5a33 in do_handle_one_connection(THD*) ()
 
No symbol table info available.
 
#18 0x00000000006a5b02 in handle_one_connection ()
 
No symbol table info available.
 
#19 0x00007fdebfb1daa1 in start_thread () from /lib64/libpthread.so.0
 
No symbol table info available.
 
#20 0x00007fdebe23693d in clone () from /lib64/libc.so.6
 
No symbol table info available.
 
 
 
Thread 2723 (Thread 0x7fccb2f6d700 (LWP 112017)):
 
#0  0x00007fdebfb21a5e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x0000000000b8f416 in wait_for_lock.isra.3 ()
 
#2  0x0000000000b900ab in thr_multi_lock ()
 
#3  0x00000000007e8444 in mysql_lock_tables(THD*, st_mysql_lock*, unsigned int) ()
 
#4  0x00000000007e9276 in mysql_lock_tables(THD*, TABLE**, unsigned int, unsigned int) ()
 
#5  0x000000000059d0b8 in lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int) ()
 
#6  0x00000000005a2b52 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) ()
 
#7  0x00000000005d83b8 in execute_sqlcom_select(THD*, TABLE_LIST*) ()
 
#8  0x00000000005e3a70 in mysql_execute_command(THD*) ()
 
#9  0x00000000005e54e7 in mysql_parse ()
 
#10 0x00000000005e795d in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
 
#11 0x00000000006a5a33 in do_handle_one_connection(THD*) ()
 
#12 0x00000000006a5b02 in handle_one_connection ()
 
#13 0x00007fdebfb1daa1 in start_thread () from /lib64/libpthread.so.0
 
#14 0x00007fdebe23693d in clone () from /lib64/libc.so.6
 
 
 
Thread 2722 (Thread 0x7fcbbf925700 (LWP 114289)):
 
#0  0x00007fdebfb21a5e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x0000000000b8f416 in wait_for_lock.isra.3 ()
 
#2  0x0000000000b900ab in thr_multi_lock ()
 
#3  0x00000000007e8444 in mysql_lock_tables(THD*, st_mysql_lock*, unsigned int) ()
 
#4  0x00000000007e9276 in mysql_lock_tables(THD*, TABLE**, unsigned int, unsigned int) ()
 
#5  0x000000000059d0b8 in lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int) ()
 
#6  0x00000000005a2b52 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) ()
 
#7  0x00000000005d83b8 in execute_sqlcom_select(THD*, TABLE_LIST*) ()
 
#8  0x00000000005e3a70 in mysql_execute_command(THD*) ()
 
#9  0x00000000005e54e7 in mysql_parse ()
 
#10 0x00000000005e795d in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
 
#11 0x00000000006a5a33 in do_handle_one_connection(THD*) ()
 
#12 0x00000000006a5b02 in handle_one_connection ()
 
#13 0x00007fdebfb1daa1 in start_thread () from /lib64/libpthread.so.0
 
#14 0x00007fdebe23693d in clone () from /lib64/libc.so.6
 
 
 
Thread 2721 (Thread 0x7fcd4144a700 (LWP 113601)):
 
#0  0x00007fdebe180625 in raise () from /lib64/libc.so.6
 
#1  0x00007fdebe181e05 in abort () from /lib64/libc.so.6
 
#2  0x00007fdebe824a7d in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib64/libstdc++.so.6
 
#3  0x00007fdebe822bd6 in ?? () from /usr/lib64/libstdc++.so.6
 
#4  0x00007fdebe822c03 in std::terminate() () from /usr/lib64/libstdc++.so.6
 
#5  0x00007fdebe82355f in __cxa_pure_virtual () from /usr/lib64/libstdc++.so.6
 
#6  0x00000000006ae6a2 in MDL_lock::can_grant_lock(enum_mdl_type, MDL_context*, bool) const ()
 
#7  0x00000000006aedc2 in MDL_context::try_acquire_lock_impl(MDL_request*, MDL_ticket**) ()
 
#8  0x00000000006af487 in MDL_context::acquire_lock(MDL_request*, unsigned long) ()
 
#9  0x0000000000599966 in open_table_get_mdl_lock(THD*, Open_table_context*, MDL_request*, unsigned int, MDL_ticket**) ()
 
#10 0x00000000005a0dfc in open_table(THD*, TABLE_LIST*, st_mem_root*, Open_table_context*) ()
 
#11 0x00000000005a28a7 in open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) ()
 
#12 0x00000000005a2b04 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) ()
 
#13 0x00000000005d83b8 in execute_sqlcom_select(THD*, TABLE_LIST*) ()
 
#14 0x00000000005e3a70 in mysql_execute_command(THD*) ()
 
#15 0x00000000005e54e7 in mysql_parse ()
 
#16 0x00000000005e795d in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
 
#17 0x00000000006a5a33 in do_handle_one_connection(THD*) ()
 
#18 0x00000000006a5b02 in handle_one_connection ()
 
#19 0x00007fdebfb1daa1 in start_thread () from /lib64/libpthread.so.0
 
#20 0x00007fdebe23693d in clone () from /lib64/libc.so.6
 
 
 
Thread 2720 (Thread 0x7fcbf296e700 (LWP 108344)):
 
#0  0x00007fdebfb21a5e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x0000000000b8f416 in wait_for_lock.isra.3 ()
 
#2  0x0000000000b900ab in thr_multi_lock ()
 
#3  0x00000000007e8444 in mysql_lock_tables(THD*, st_mysql_lock*, unsigned int) ()
 
#4  0x00000000007e9276 in mysql_lock_tables(THD*, TABLE**, unsigned int, unsigned int) ()
 
#5  0x000000000059d0b8 in lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int) ()
 
#6  0x00000000005a2b52 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) ()
 
#7  0x00000000005d83b8 in execute_sqlcom_select(THD*, TABLE_LIST*) ()
 
#8  0x00000000005e3a70 in mysql_execute_command(THD*) ()
 
#9  0x00000000005e54e7 in mysql_parse ()
 
#10 0x00000000005e795d in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
 
#11 0x00000000006a5a33 in do_handle_one_connection(THD*) ()
 
#12 0x00000000006a5b02 in handle_one_connection ()
 
#13 0x00007fdebfb1daa1 in start_thread () from /lib64/libpthread.so.0
 
#14 0x00007fdebe23693d in clone () from /lib64/libc.so.6
 
 
 
Thread 2719 (Thread 0x7fcc6c893700 (LWP 111635)):
 
#0  0x00007fdebfb21a5e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x0000000000b8f416 in wait_for_lock.isra.3 ()
 
#2  0x0000000000b900ab in thr_multi_lock ()
 
#3  0x00000000007e8444 in mysql_lock_tables(THD*, st_mysql_lock*, unsigned int) ()
 
#4  0x00000000007e9276 in mysql_lock_tables(THD*, TABLE**, unsigned int, unsigned int) ()
 
#5  0x000000000059d0b8 in lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int) ()
 
#6  0x00000000005a2b52 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) ()
 
#7  0x00000000005d83b8 in execute_sqlcom_select(THD*, TABLE_LIST*) ()
 
#8  0x00000000005e3a70 in mysql_execute_command(THD*) ()
 
#9  0x00000000005e54e7 in mysql_parse ()
 
#10 0x00000000005e795d in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
 
#11 0x00000000006a5a33 in do_handle_one_connection(THD*) ()
 
#12 0x00000000006a5b02 in handle_one_connection ()
 
#13 0x00007fdebfb1daa1 in start_thread () from /lib64/libpthread.so.0
 
#14 0x00007fdebe23693d in clone () from /lib64/libc.so.6



 Comments   
Comment by Sergey Vojtovich [ 2016-07-12 ]

These pure virtual methods are most probably incompatible_waiting_types_bitmap()/incompatible_granted_types_bitmap(). One of possible reasons for this might be that we access destroyed MDL_lock object.

Comment by Fenero Support [ 2016-07-12 ]

Just happened again. Here's the info .err and GDB bt

ure virtual method called
 
pure virtual method called
 
pure virtual method called
 
pure virtual method called
 
pure virtual method called
 
pure virtual method called
 
terminate called recursively
 
terminate called recursively
 
160712 16:11:54 [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.24-MariaDB
 
key_buffer_size=6442450944
 
read_buffer_size=2097152
 
max_used_connections=2727
 
max_threads=5002
 
thread_count=2698
 
It is possible that mysqld could use up to
 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 26878534 K  bytes of memory
 
terminate called recursively
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0x7f677bdf8008
 
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...
 
terminate called recursively
 
terminate called recursively
 
terminate called without an active exception
 
pure virtual method called
 
terminate called recursively
 
160712 16:12:54 mysqld_safe Number of processes running now: 0
 
160712 16:12:54 mysqld_safe mysqld restarted

BT

 
Core was generated by `/usr/sbin/mysqld --basedir=/usr --datadir=/mnt/db_data/mysql --plugin-dir=/usr/'.
 
Program terminated with signal 6, Aborted.
 
#0  0x00007f74991b4625 in raise () from /lib64/libc.so.6
 
Missing separate debuginfos, use: debuginfo-install MariaDB-server-10.0.24-1.el6.x86_64
 
(gdb) bt
 
#0  0x00007f74991b4625 in raise () from /lib64/libc.so.6
 
#1  0x00007f74991b5e05 in abort () from /lib64/libc.so.6
 
#2  0x00007f7499858991 in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib64/libstdc++.so.6
 
#3  0x00007f7499856bd6 in ?? () from /usr/lib64/libstdc++.so.6
 
#4  0x00007f7499856c03 in std::terminate() () from /usr/lib64/libstdc++.so.6
 
#5  0x00007f749985755f in __cxa_pure_virtual () from /usr/lib64/libstdc++.so.6
 
#6  0x00000000006ae6a2 in MDL_lock::can_grant_lock(enum_mdl_type, MDL_context*, bool) const ()
 
#7  0x00000000006aedc2 in MDL_context::try_acquire_lock_impl(MDL_request*, MDL_ticket**) ()
 
#8  0x00000000006af487 in MDL_context::acquire_lock(MDL_request*, unsigned long) ()
 
#9  0x0000000000599966 in open_table_get_mdl_lock(THD*, Open_table_context*, MDL_request*, unsigned int, MDL_ticket**) ()
 
#10 0x00000000005a0dfc in open_table(THD*, TABLE_LIST*, st_mem_root*, Open_table_context*) ()
 
#11 0x00000000005a28a7 in open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) ()
 
#12 0x00000000005a2b04 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) ()
 
#13 0x00000000005d83b8 in execute_sqlcom_select(THD*, TABLE_LIST*) ()
 
#14 0x00000000005e3a70 in mysql_execute_command(THD*) ()
 
#15 0x00000000005e54e7 in mysql_parse ()
 
#16 0x00000000005e795d in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
 
#17 0x00000000006a5a33 in do_handle_one_connection(THD*) ()
 
#18 0x00000000006a5b02 in handle_one_connection ()
 
#19 0x00007f749ab51aa1 in start_thread () from /lib64/libpthread.so.0
 
#20 0x00007f749926a93d in clone () from /lib64/libc.so.6
 
(gdb) bt full
 
#0  0x00007f74991b4625 in raise () from /lib64/libc.so.6
 
No symbol table info available.
 
#1  0x00007f74991b5e05 in abort () from /lib64/libc.so.6
 
No symbol table info available.
 
#2  0x00007f7499858991 in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib64/libstdc++.so.6
 
No symbol table info available.
 
#3  0x00007f7499856bd6 in ?? () from /usr/lib64/libstdc++.so.6
 
No symbol table info available.
 
#4  0x00007f7499856c03 in std::terminate() () from /usr/lib64/libstdc++.so.6
 
No symbol table info available.
 
#5  0x00007f749985755f in __cxa_pure_virtual () from /usr/lib64/libstdc++.so.6
 
No symbol table info available.
 
#6  0x00000000006ae6a2 in MDL_lock::can_grant_lock(enum_mdl_type, MDL_context*, bool) const ()
 
No symbol table info available.
 
#7  0x00000000006aedc2 in MDL_context::try_acquire_lock_impl(MDL_request*, MDL_ticket**) ()
 
No symbol table info available.
 
#8  0x00000000006af487 in MDL_context::acquire_lock(MDL_request*, unsigned long) ()
 
No symbol table info available.
 
#9  0x0000000000599966 in open_table_get_mdl_lock(THD*, Open_table_context*, MDL_request*, unsigned int, MDL_ticket**) ()
 
No symbol table info available.
 
#10 0x00000000005a0dfc in open_table(THD*, TABLE_LIST*, st_mem_root*, Open_table_context*) ()
 
No symbol table info available.
 
#11 0x00000000005a28a7 in open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) ()
 
No symbol table info available.
 
#12 0x00000000005a2b04 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) ()
 
No symbol table info available.
 
#13 0x00000000005d83b8 in execute_sqlcom_select(THD*, TABLE_LIST*) ()
 
No symbol table info available.
 
#14 0x00000000005e3a70 in mysql_execute_command(THD*) ()
 
No symbol table info available.
 
#15 0x00000000005e54e7 in mysql_parse ()
 
No symbol table info available.
 
#16 0x00000000005e795d in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
 
No symbol table info available.
 
#17 0x00000000006a5a33 in do_handle_one_connection(THD*) ()
 
No symbol table info available.
 
#18 0x00000000006a5b02 in handle_one_connection ()
 
No symbol table info available.
 
#19 0x00007f749ab51aa1 in start_thread () from /lib64/libpthread.so.0
 
---Type <return> to continue, or q <return> to quit---

Comment by Elena Stepanova [ 2016-07-15 ]

fenero,

Is there anything you can tell us about the workflow and circumstances that might help to identify the problem?
Maybe it happens at certain moments, when the server performs some maintenance works (backups or such), or any other regular but not permanent activities?
What kind of workflow the server runs? The crash happened upon SELECT, are there normally many threads that select from the same table, or is it a mix of SELECTs and UPDATEs, or maybe a mix of SELECTs and DDL?
Which engines are used?
Please also attach your cnf files.

With 2.5K threads running at the same time, and error log not even containing the ID of the connection where it crashed, there is no point asking for the general log, even if you were able to enable it (which you most likely can't, given the load on the server).

Comment by Elena Stepanova [ 2016-08-16 ]

svoj, is the stack trace above any help? Maybe you've fixed or seen something similar recently?

Comment by Sergey Vojtovich [ 2016-08-17 ]

elenst, nope it doesn't look familiar.

How many tables are being accessed by these 2.5k threads?
What are the values of metadata_locks_cache_size and metadata_locks_hash_instances?
Is metadata_lock_info plugin being used?

Comment by Elena Stepanova [ 2016-09-14 ]

fenero, is it still happening? Do you have any more information?

Comment by Elena Stepanova [ 2016-10-12 ]

Please comment to re-open if you have further information on the issue.

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