[MDEV-19966] GaleraCluster's one node is Crashed down when many concurrent update was issuing. Created: 2019-07-05  Updated: 2020-07-01  Resolved: 2019-10-31

Status: Closed
Project: MariaDB Server
Component/s: Galera
Affects Version/s: 10.4.6
Fix Version/s: 10.4.9

Type: Bug Priority: Critical
Reporter: Seonghwan Kim Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 2
Labels: None
Environment:

VMWare, 3-node Galera Cluster, CentOS7


Attachments: File galera_multi.cnf     File galera_multi.test    
Issue Links:
Relates
relates to MDEV-23064 Crashed node under Galera Closed
relates to MDEV-20047 Nodes are randomly crashing Closed

 Description   

*Galera Cluster was crashed down, when one record was concurrently updating from many connections.
*
*Table description
create table notice(
id int auto_increment,
host_id varchar(50),
mdate datetime,
primary key(id));

*Only 3 record was inserted
insert into notice(host_id, mdate) values(concat(@@hostname, '--', connection_id(), '--', now()), now());
insert into notice(host_id, mdate) values(concat(@@hostname, '--', connection_id(), '--', now()), now());
insert into notice(host_id, mdate) values(concat(@@hostname, '--', connection_id(), '--', now()), now());

*30 connections(3*10 connection) were issuing below same query.
update notice set host_id = concat(@@hostname, '--', connection_id(), '--', now()) where id = 4;

*set global wsrep_retry_autocommit=30;

*Error Log is like below.

mysqld: /home/buildbot/buildbot/build/wsrep-lib/src/client_state.cpp:232: int wsrep::client_state::after_statement(): Assertion `transaction_.state() == wsrep::transaction::s_aborted' failed.
190705 17:28:21 [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.4.6-MariaDB-log
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=11
max_threads=153
thread_count=20
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467732 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fd6d404e008
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 = 0x7fd6e41c9eb0 thread_stack 0x49000
/GALERA/galera/bin/mysqld(my_print_stacktrace+0x2b)[0x561df71ce93b]
/GALERA/galera/bin/mysqld(handle_fatal_signal+0x4b7)[0x561df6c2f737]
sigaction.c:0(__restore_rt)[0x7fd6f89276d0]
:0(__GI_raise)[0x7fd6f7d73277]
:0(__GI_abort)[0x7fd6f7d74968]
:0(__assert_fail_base)[0x7fd6f7d6c096]
:0(_GI__assert_fail)[0x7fd6f7d6c142]
/GALERA/galera/bin/mysqld(_ZN5wsrep12client_state15after_statementEv+0x1bc)[0x561df72586ec]
src/client_state.cpp:258(wsrep::client_state::after_statement())[0x561df69b0bcc]
sql/wsrep_trans_observer.h:385(wsrep_after_statement)[0x561df69b77a4]
sql/sp_head.cc:3514(sp_instr_stmt::execute(THD*, unsigned int*))[0x561df69b7fc9]
sql/sp_head.cc:1348(sp_head::execute(THD*, bool))[0x561df69b42b4]
sql/sp_head.cc:1758(sp_head::execute_trigger(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, st_grant_info*))[0x561df69b4a92]
sql/sql_trigger.cc:2203(Table_triggers_list::process_triggers(THD*, trg_event_type, trg_action_time_type, bool))[0x561df6ad7cae]
sql/sql_update.cc:1101(mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, bool, unsigned long long*, unsigned long long*))[0x561df6ae48d0]
sql/sql_parse.cc:4365(mysql_execute_command(THD*))[0x561df6a49dde]
sql/sql_parse.cc:10013(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x561df6a4c5e1]
sql/sql_class.h:3881(THD::get_stmt_da())[0x561df6a4c76a]
sql/sql_parse.cc:1813(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x561df6a4ee44]
sql/sql_parse.cc:1362(do_command(THD*))[0x561df6a4f561]
sql/sql_connect.cc:1403(do_handle_one_connection(CONNECT*))[0x561df6b1e87f]
sql/sql_connect.cc:1308(handle_one_connection)[0x561df6b1e9c4]
pthread_create.c:0(start_thread)[0x7fd6f891fe25]
/lib64/libc.so.6(clone+0x6d)[0x7fd6f7e3bbad]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fd6d42ef270): is an invalid pointer
Connection ID (thread ID): 16
Status: KILL_QUERY

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=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,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: insert into notice_log(hostname, connection_id, time) values(@@hostname, connection_id(), now())

Writing a core file...
Working directory at /GALERA_DATA/DATA
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 0 unlimited bytes
Max resident set unlimited unlimited bytes
Max processes 3802 3802 processes
Max open files 65535 65535 files
Max locked memory 65536 65536 bytes
Max address space unlimited unlimited bytes
Max file locks unlimited unlimited locks
Max pending signals 3802 3802 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



 Comments   
Comment by Jan Lindström (Inactive) [ 2019-07-09 ]

I could not easily repeat this with 3 node cluster. Attaching my test case as a reference.

Comment by Seonghwan Kim [ 2019-07-10 ]

Not repeat with using procedure.
Using 'SecureCRT' for open 30 windows(node per 10 windows) and using [Send commands to all sessions] windows for test.
Issuing 'enter' key excessively with same query 'update notice set...' again, again and again repeatedly in the very short time, then you will may get the same result.

Comment by Seonghwan Kim [ 2019-08-09 ]

trigger is also needed.

create table notice_log(hostname varchar(12), connection_id varchar(12), time datetime);

DELIMITER $$
CREATE TRIGGER UpdateTrigger
AFTER UPDATE ON notice
FOR EACH ROW
BEGIN
insert into notice_log(hostname, connection_id, time) values(@@hostname, connection_id(), now());
END $$
DELIMITER ;

Comment by Jan Lindström (Inactive) [ 2019-10-31 ]

I added the trigger and still can't repeat with latest i.e. 10.4.9.

Comment by Leon Koens [ 2020-01-28 ]

I ran into this bug with version 10.4.11 on a 3 node cluster. For me it was a delete query with a trigger that does an insert.

The table the delete query deletes from:

CREATE TABLE `warehouse_voorraad_bin` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `voorraad_id` int(11) NOT NULL,
  `bin_id` int(10) unsigned NOT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `voorraad_id_UNIQUE` (`voorraad_id`),
  KEY `fk_voorraad_bins_bins1_idx` (`bin_id`),
  CONSTRAINT `fk_voorraad_bins_bins2` FOREIGN KEY (`bin_id`) REFERENCES `warehouse_bins` (`id`) ON DELETE NO ACTION ON UPDATE NO ACTION
) ENGINE=InnoDB AUTO_INCREMENT=3824151 DEFAULT CHARSET=latin1 ROW_FORMAT=DYNAMIC

The trigger that does an insert:

CREATE DEFINER=`root`@`localhost` TRIGGER voorraad_bin_locatie_delete
BEFORE DELETE ON warehouse_voorraad_bin
    FOR EACH ROW
           BEGIN
                 INSERT INTO voorraadItemHistory
                             (voorraad_id,statusType,value, newValue)
                      VALUES
                             (OLD.voorraad_id,'bin', OLD.bin_id, NULL);
             END

Which caused the following error:

mysqld: /home/buildbot/buildbot/build/mariadb-10.4.11/wsrep-lib/src/client_state.cpp:236: int wsrep::client_state::after_statement(): Assertion `transaction_.state() == wsrep::transaction::s_aborted' failed.
200127 15:46:05 [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.4.11-MariaDB-1:10.4.11+maria~bionic-log
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=194
max_threads=514
thread_count=203
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2314852 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x7f79f4000c08
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 = 0x7f7c01b95dd8 thread_stack 0x49000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55d2bac5d1de]
/usr/sbin/mysqld(handle_fatal_signal+0x515)[0x55d2ba6d22f5]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890)[0x7fb3a2f2f890]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xc7)[0x7fb3a1863e97]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x141)[0x7fb3a1865801]
/lib/x86_64-linux-gnu/libc.so.6(+0x3039a)[0x7fb3a185539a]
/lib/x86_64-linux-gnu/libc.so.6(+0x30412)[0x7fb3a1855412]
/usr/sbin/mysqld(_ZN5wsrep12client_state15after_statementEv+0x3c1)[0x55d2bacc72a1]
/usr/sbin/mysqld(_ZN7sp_head7executeEP3THDb+0x1034)[0x55d2ba429414]
/usr/sbin/mysqld(_ZN7sp_head15execute_triggerEP3THDPK25st_mysql_const_lex_stringS4_P13st_grant_info+0x1b1)[0x55d2ba429a11]
/usr/sbin/mysqld(_ZN19Table_triggers_list16process_triggersEP3THD14trg_event_type20trg_action_time_typeb+0x10c)[0x55d2ba559a1c]
/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyyP13select_result+0x1509)[0x55d2ba8162a9]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x17a1)[0x55d2ba4bf0f1]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x22a)[0x55d2ba4c647a]
/usr/sbin/mysqld(+0x658cd6)[0x55d2ba4c6cd6]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x230f)[0x55d2ba4c996f]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x148)[0x55d2ba4ca2d8]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x203)[0x55d2ba5a6253]
/usr/sbin/mysqld(handle_one_connection+0x3d)[0x55d2ba5a636d]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db)[0x7fb3a2f246db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7fb3a194688f]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f79f400ffe0): DELETE FROM `warehouse_voorraad_bin` WHERE `id`='3820623'
Connection ID (thread ID): 4511374
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=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,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.
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 0 unlimited bytes
Max resident set unlimited unlimited bytes
Max processes 1030219 1030219 processes
Max open files 16364 16364 files
Max locked memory 16777216 16777216 bytes
Max address space unlimited unlimited bytes
Max file locks unlimited unlimited locks
Max pending signals 1030219 1030219 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: |/usr/share/apport/apport %p %s %c %d %P

Comment by Martin Kovachev [ 2020-07-01 ]

I believe my issue may be related or the same as this one!

Generated at Thu Feb 08 08:55:42 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.