[MDEV-24397] MariaDB Galera Server Crashes on Large DELETE Created: 2020-12-11  Updated: 2022-03-16  Resolved: 2021-12-23

Status: Closed
Project: MariaDB Server
Component/s: Data Manipulation - Delete, Galera
Affects Version/s: 10.5.8
Fix Version/s: 10.5.13

Type: Bug Priority: Major
Reporter: Larry Adams Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: crash, galera
Environment:

CentOS 8.2, 3 Node Galera Cluster

Attachments: Text File gdb.txt     Text File gdb_output.log     File server.cnf    
Issue Links:
Blocks
blocks MDEV-24398 MariaDB Galera Connect Timeout and Re... Closed
Relates
relates to MDEV-23851 Galera assertion at lock0lock.cc line... Closed
relates to MDEV-25114 Crash: WSREP: invalid state ROLLED_BA... Closed

 Description   

We are attempting to deploy Galera on a large high I/O environment, and the cluster continues to loose state due to failing MariaDB servers. The server continues to segfault trying to roll forward transactions. It eventually comes up, but then other servers are expelled from the cluster. We are running from the MariaDB.repo on MariaDB-Server-10.5.8-1

The backtrace looks like the following:

201211  8:50:43 [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 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.5.8-MariaDB-log
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=0
 
max_threads=1502
 
thread_count=10
 
It is possible that mysqld could use up to
 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 307971051 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7e0470000c58
 
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 = 0x7f0b5c091c18 thread_stack 0x49000
 
??:0(my_print_stacktrace)[0x559329b4c07e]
 
??:0(handle_fatal_signal)[0x5593295e15e5]
 
sigaction.c:0(__restore_rt)[0x7f0b606bddd0]
 
??:0(wsrep_thd_LOCK)[0x559329882612]
 
??:0(wsrep_notify_status(wsrep::server_state::state, wsrep::view const*))[0x5593298a6269]
 
??:0(wsrep_notify_status(wsrep::server_state::state, wsrep::view const*))[0x5593298ebb83]
 
??:0(wsrep_notify_status(wsrep::server_state::state, wsrep::view const*))[0x5593298ee986]
 
??:0(wsrep_notify_status(wsrep::server_state::state, wsrep::view const*))[0x5593298f41b5]
 
??:0(void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char*>(char*, char*, std::forward_iterator_tag))[0x55932997e910]
 
??:0(void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char*>(char*, char*, std::forward_iterator_tag))[0x559329984bdb]
 
??:0(wsrep_notify_status(wsrep::server_state::state, wsrep::view const*))[0x5593298ae890]
 
??:0(handler::ha_rnd_pos(unsigned char*, unsigned char*))[0x5593295e7c7a]
 
??:0(Rows_log_event::find_row(rpl_group_info*))[0x5593296e2e65]
 
??:0(Delete_rows_log_event::do_exec_row(rpl_group_info*))[0x5593296e2fa9]
 
??:0(Rows_log_event::do_apply_event(rpl_group_info*))[0x5593296d75bc]
 
??:0(wsrep_apply_events(THD*, Relay_log_info*, void const*, unsigned long))[0x55932987a29c]
 
??:0(Wsrep_applier_service::apply_write_set(wsrep::ws_meta const&, wsrep::const_buffer const&, wsrep::mutable_buffer&))[0x5593298638e4]
 
??:0(wsrep::server_state::start_streaming_applier(wsrep::id const&, wsrep::transaction_id const&, wsrep::high_priority_service*))[0x559329bd2b32]
 
??:0(wsrep::server_state::on_apply(wsrep::high_priority_service&, wsrep::ws_handle const&, wsrep::ws_meta const&, wsrep::const_buffer const&))[0x559329bd378d]
 
??:0(wsrep::wsrep_provider_v26::options[abi:cxx11]() const)[0x559329be7164]
 
src/trx_handle.cpp:387(galera::TrxHandleSlave::apply(void*, wsrep_cb_status (*)(void*, wsrep_ws_handle const*, unsigned int, wsrep_buf const*, wsrep_trx_meta const*, bool*), wsrep_trx_meta const&, bool&))[0x7f0b5c7f0224]
 
src/replicator_smm.cpp:504(galera::ReplicatorSMM::apply_trx(void*, galera::TrxHandleSlave&))[0x7f0b5c82de88]
 
src/gu_logger.hpp:96(galera::ReplicatorSMM::process_IST_writeset(void*, boost::shared_ptr<galera::TrxHandleSlave> const&))[0x7f0b5c83c9ef]
 
src/replicator_str.cpp:1155(galera::ReplicatorSMM::recv_IST(void*))[0x7f0b5c83eff1]
 
src/replicator_smm.cpp:396(galera::ReplicatorSMM::async_recv(void*))[0x7f0b5c83319b]
 
src/wsrep_provider.cpp:263(galera_recv)[0x7f0b5c848528]
 
??:0(wsrep::wsrep_provider_v26::run_applier(wsrep::high_priority_service*))[0x559329be782e]
 
??:0(wsrep_fire_rollbacker)[0x55932987c333]
 
??:0(start_wsrep_THD(void*))[0x55932986e60f]
 
??:0(MyCTX_nopad::finish(unsigned char*, unsigned int*))[0x5593298015da]
 
pthread_create.c:0(start_thread)[0x7f0b606b32de]
 
:0(__GI___clone)[0x7f0b5e520e83]
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7f0a63079643): DELETE FROM poller_output WHERE local_data_id IN (144518,144521,144521,144524,144524,144527,144527,144530,144530,144641,144641,144644,144644,144647,144647,144650,144650,144653,144653,144656,144656,144659,144659,144662,144662,144665,144665,144770,144770,144773,144773,144776,144776,144779,144779,144782,144782,144785,144785,144788,144788,144896,144896,144899,144899,144902,144902,144905,144905,144908,144908,144911,144911,144914,144914,144917,144917,144920,144920,144923,144923,145025,145025,145028,145028,145031,145031,145034,145034,145037,145037,145040,145040,145043,145043,145154,145154,145157,145157,145160,145160,145163,145163,145166,145166,145169,145169,145172,145172,145175,145175,145178,145178,145280,145280,145283,145283,145286,145286,145289,145289,145292,145292,145295,145295,145298,145298,145409,145409,145412,145412,145415,145415,145418,145418,145421,145421,145424,145424,145427,145427,145430,145430,145433,145433,145538,145538,145541,145541,145544,145544,145547,145547,145550,145550,145553,145553,145556,145556,145664,145664,145667,145667,145670,145670,145673,145673,145676,145676,145679,145679,145682,145682,145685,145685,145688,145688,145691,145691,145793,145793,145796,145796,145799,145799,145802,145802,145805,145805,145808,145808,145811,145811,145922,145922,145925,145925,145928,145928,145931,145931,145934,145934,145937,145937,145940,145940,145943,145943,145946,145946,146048,146048,146051,146051,146054,146054,146057,146057,146060,146060,146063,146063,146066,146066,146177,146180,146183,146186,146189,146192,146195,146198,146201,146306,146309,146312,146315,146318,146321,146324,146432,146435,146438,146441,146444,146447,146450,146453,146456,146459,146561,146564,146567,146570

I've truncated the query as it's fairly large.

 Comments   
Comment by Larry Adams [ 2020-12-11 ]

I have added the debug RPM's and since then, have not experience this bug again. Once I get a better backtrace, I'll upload it. I've got some core files, but they are pretty big.

Comment by Daniel Black [ 2020-12-11 ]

Can you include `SHOW CREATE TABLE poller_output`, server configuration and galera library version?

If you have a core dump you from this crash (is it in coredumpct output?) you can get the backtrace from that after the event occurred - https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/#analyzing-a-core-file-with-gdb-on-linux

Comment by Larry Adams [ 2020-12-12 ]

Daniel, I'll do that. Here is the simple backtrace. The full thread backtrace I'll upload shortly.

#0 0x00007f597f8fb70f in raise () from /lib64/libc.so.6
#1 0x00007f597f8e5bee in abort () from /lib64/libc.so.6
#2 0x000056320a4f6985 in ut_dbg_assertion_failed (expr=expr@entry=0x0, file=file@entry=0x56320afbab50 "/home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.5.8/storage/innobase/lock/lock0lock.cc", line=line@entry=655)
at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/ut/ut0dbg.cc:60
#3 0x000056320a4d2cc5 in wsrep_assert_no_bf_bf_wait (lock_rec1=0x0, lock_rec2=0x7f596c1c73a0, trx1=0x7f596c1cb5a8) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/lock/lock0lock.cc:655
#4 0x000056320ab20944 in lock_rec_has_to_wait (for_locking=true, lock_is_on_supremum=true, lock2=0x7f596c1c73a0, type_mode=2563, trx=0x7f596c1cb5a8) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/lock/lock0lock.cc:767
#5 lock_rec_other_has_conflicting (mode=mode@entry=2563, block=block@entry=0x7f592c1b3900, heap_no=heap_no@entry=1, trx=trx@entry=0x7f596c1cb5a8) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/lock/lock0lock.cc:1093
#6 0x000056320ab25d6a in lock_rec_insert_check_and_lock (flags=flags@entry=0, rec=rec@entry=0x7f5932ee132c <error: Cannot access memory at address 0x7f5932ee132c>, block=0x7f592c1b3900, index=index@entry=0x7e54e8083e70, thr=thr@entry=0x7e54e82569f8,
mtr=mtr@entry=0x7f595c4736f0, inherit=<optimized out>) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/lock/lock0lock.cc:5138
#7 0x000056320ac32483 in btr_cur_ins_lock_and_undo (inherit=0x7f595c472a47, mtr=0x7f595c4736f0, thr=0x7e54e82569f8, entry=0x7e54e802c720, cursor=0x7f595c472d30, flags=0) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/btr/btr0cur.cc:3264
#8 btr_cur_optimistic_insert (flags=flags@entry=0, cursor=cursor@entry=0x7f595c472d30, offsets=offsets@entry=0x7f595c472cd8, heap=heap@entry=0x7f595c472cd0, entry=entry@entry=0x7e54e802c720, rec=rec@entry=0x7f595c473190, big_rec=0x7f595c472cc8,
n_ext=<optimized out>, thr=0x7e54e82569f8, mtr=0x7f595c4736f0) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/btr/btr0cur.cc:3502
#9 0x000056320ab834d5 in row_ins_clust_index_entry_low (flags=0, mode=<optimized out>, index=0x7e54e8083e70, n_uniq=<optimized out>, entry=0x7e54e802c720, n_ext=0, thr=0x7e54e82569f8)
at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/row/row0ins.cc:2724
#10 0x000056320ab874e6 in row_ins_clust_index_entry (index=0x7e54e8083e70, entry=0x7e54e802c720, thr=0x7e54e82569f8, n_ext=0) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/row/row0ins.cc:3196
#11 0x000056320ab880b4 in row_ins_index_entry (thr=0x7e54e82569f8, entry=<optimized out>, index=<optimized out>) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/row/row0ins.cc:3321
#12 row_ins_index_entry_step (thr=0x7e54e82569f8, node=<optimized out>) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/row/row0ins.cc:3490
#13 row_ins (thr=0x7e54e82569f8, node=<optimized out>) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/row/row0ins.cc:3627
#14 row_ins_step (thr=thr@entry=0x7e54e82569f8) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/row/row0ins.cc:3766
#15 0x000056320ab99967 in row_insert_for_mysql (mysql_rec=<optimized out>, prebuilt=<optimized out>, ins_mode=<optimized out>) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/row/row0mysql.cc:1421
#16 0x000056320aae0229 in ha_innobase::write_row(unsigned char const*) () at /usr/src/debug/MariaDB-10.5.8/src_0/storage/innobase/handler/ha_innodb.cc:7592
#17 0x000056320a820e4f in handler::ha_write_row (this=0x7e55000db4d0, buf=0x7e55000fea90 "\327v\002") at /usr/src/debug/MariaDB-10.5.8/src_0/sql/handler.cc:7146
#18 0x000056320a913f45 in Rows_log_event::write_row (this=this@entry=0x7e54e4023a18, rgi=rgi@entry=0x7e54e401c9f0, overwrite=false) at /usr/src/debug/MariaDB-10.5.8/src_0/sql/log_event_server.cc:7282
#19 0x000056320a9144fd in Write_rows_log_event::do_exec_row (this=0x7e54e4023a18, rgi=0x7e54e401c9f0) at /usr/src/debug/MariaDB-10.5.8/src_0/sql/log_event_server.cc:7502
#20 0x000056320a9095bc in Rows_log_event::do_apply_event (this=0x7e54e4023a18, rgi=0x7e54e401c9f0) at /usr/src/debug/MariaDB-10.5.8/src_0/sql/log_event_server.cc:5672
#21 0x000056320aaac29c in Log_event::apply_event (rgi=0x7e54e401c9f0, this=0x7e54e4023a18) at /usr/src/debug/MariaDB-10.5.8/src_0/sql/log_event.h:1498
#22 wsrep_apply_events (thd=thd@entry=0x7e54e4000c58, rli=<optimized out>, events_buf=<optimized out>, buf_len=0) at /usr/src/debug/MariaDB-10.5.8/src_0/sql/wsrep_applier.cc:208
#23 0x000056320aa958e4 in apply_events (err=..., data=..., rli=<optimized out>, thd=0x7e54e4000c58) at /usr/src/debug/MariaDB-10.5.8/src_0/wsrep-lib/include/wsrep/buffer.hpp:48
#24 Wsrep_applier_service::apply_write_set (this=0x7f595c475b40, ws_meta=..., data=..., err=...) at /usr/src/debug/MariaDB-10.5.8/src_0/sql/wsrep_high_priority_service.cc:541
#25 0x000056320ae04b32 in apply_write_set (server_state=..., high_priority_service=..., ws_handle=..., ws_meta=..., data=...) at /usr/src/debug/MariaDB-10.5.8/src_0/wsrep-lib/src/server_state.cpp:327
#26 0x000056320ae0578d in wsrep::server_state::on_apply (this=<optimized out>, high_priority_service=..., ws_handle=..., ws_meta=..., data=...) at /usr/src/debug/MariaDB-10.5.8/src_0/wsrep-lib/src/server_state.cpp:1136
#27 0x000056320ae19164 in wsrep::high_priority_service::apply (data=..., ws_meta=..., ws_handle=..., this=0x7f595c475b40) at /usr/src/debug/MariaDB-10.5.8/src_0/wsrep-lib/include/wsrep/high_priority_service.hpp:47
#28 (anonymous namespace)::apply_cb (ctx=0x7f595c475b40, wsh=<optimized out>, flags=<optimized out>, buf=<optimized out>, meta=<optimized out>, exit_loop=0x7f595c474e7f) at /usr/src/debug/MariaDB-10.5.8/src_0/wsrep-lib/src/wsrep_provider_v26.cpp:502
#29 0x00007f597dc8f224 in galera::TrxHandleSlave::apply (this=this@entry=0x7e52a00f0610, recv_ctx=recv_ctx@entry=0x7f595c475b40,
apply_cb=0x56320ae19030 <(anonymous namespace)::apply_cb(void*, wsrep_ws_handle_t const*, uint32_t, wsrep_buf_t const*, wsrep_trx_meta_t const*, wsrep_bool_t*)>, meta=..., exit_loop=exit_loop@entry=@0x7f595c474e7f: false)
at galera/src/trx_handle.cpp:391
#30 0x00007f597dccce88 in galera::ReplicatorSMM::apply_trx (this=0x56320c30cdb0, recv_ctx=0x7f595c475b40, ts=...) at galera/src/replicator_smm.cpp:504
#31 0x00007f597dcd1d3e in galera::ReplicatorSMM::process_trx (this=0x56320c30cdb0, recv_ctx=0x7f595c475b40, ts_ptr=...) at galera/src/replicator_smm.cpp:2127
#32 0x00007f597dcab89f in galera::GcsActionSource::process_writeset (this=0x56320c3178d0, recv_ctx=0x7f595c475b40, act=..., exit_loop=@0x7f595c47574f: false) at galera/src/gcs_action_source.cpp:62
#33 0x00007f597dcac192 in galera::GcsActionSource::dispatch (this=<optimized out>, recv_ctx=<optimized out>, act=..., exit_loop=<optimized out>) at galera/src/gcs_action_source.cpp:110
#34 0x00007f597dcac4a1 in galera::GcsActionSource::process (this=0x56320c3178d0, recv_ctx=0x7f595c475b40, exit_loop=@0x7f595c47574f: false) at galera/src/gcs_action_source.cpp:183
#35 0x00007f597dcd2100 in galera::ReplicatorSMM::async_recv (this=0x56320c30cdb0, recv_ctx=0x7f595c475b40) at galera/src/replicator_smm.cpp:390
#36 0x00007f597dce7528 in galera_recv (gh=<optimized out>, recv_ctx=<optimized out>) at galera/src/wsrep_provider.cpp:236
#37 0x000056320ae1982e in wsrep::wsrep_provider_v26::run_applier (this=<optimized out>, applier_ctx=<optimized out>) at /usr/src/debug/MariaDB-10.5.8/src_0/wsrep-lib/src/wsrep_provider_v26.cpp:740
#38 0x000056320aaae333 in wsrep_replication_process (thd=0x7e54e4000c58, arg=<optimized out>) at /usr/src/debug/MariaDB-10.5.8/src_0/wsrep-lib/include/wsrep/server_state.hpp:308
#39 0x000056320aaa060f in start_wsrep_THD (arg=arg@entry=0x56367ad66000) at /usr/src/debug/MariaDB-10.5.8/src_0/sql/wsrep_mysqld.h:553
#40 0x000056320aa335da in pfs_spawn_thread (arg=0x56320c4499e8) at /usr/src/debug/MariaDB-10.5.8/src_0/storage/perfschema/pfs.cc:2201
#41 0x00007f5981b522de in start_thread () from /lib64/libpthread.so.0
#42 0x00007f597f9bfe83 in clone () from /lib64/libc.so.6

Comment by Larry Adams [ 2020-12-12 ]

The inserts can be fairly large upto 16MB or so. The number of rows affected can be > 100k.

CREATE TABLE `poller_output` (
`local_data_id` mediumint(8) unsigned NOT NULL DEFAULT 0,
`rrd_name` varchar(19) COLLATE utf8mb4_unicode_ci NOT NULL DEFAULT '',
`time` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
`output` varchar(512) COLLATE utf8mb4_unicode_ci NOT NULL DEFAULT '',
PRIMARY KEY (`local_data_id`,`rrd_name`,`time`) USING BTREE
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci

Comment by Larry Adams [ 2020-12-12 ]

Daniel,

I have a half a dozen cores per server. There is another ticket as well, same kind of issue in that the server looses sync, but does not crash, until the OOM killer takes it that is.

Server is a DELL, with CentOS8.2
uname -a
Linux rtm-db-03 4.18.0-193.14.2.el8_2.x86_64 #1 SMP Sun Jul 26 03:54:29 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

[root@rtm-db-03 tmp]# free -g
total used free shared buff/cache available
Mem: 1510 4 1167 0 338 1498

[root@rtm-db-03 tmp]# cat /proc/cpuinfo | grep cpuid | wc -l
224

Larry

Comment by Larry Adams [ 2020-12-12 ]

Okay, on the tertiary server, 3 of the cores had the same short bt stack count of 42, and ended with the call to clone(), like the attached. The others were from me doing a kill -9, so not so relevant.

Comment by Larry Adams [ 2020-12-12 ]

gdb.txt -> issue with grcache recovery to memory leak too oom killer
gdb_output.log -> this issue.

Comment by Larry Adams [ 2021-01-12 ]

We are still not in production. So, I have a small window to test a fix before I'll have to stick with 10.5.6, which has been stable.

Comment by Larry Adams [ 2021-03-09 ]

I've switched from Galera to Async Parallel Replication due to the OPTIMIZE causing the entire cluster to pause. Replication is working, but I'm loosing my hair slowly but surely trying to figure things out, or maybe it's just my age...

Comment by Jan Lindström (Inactive) [ 2022-03-16 ]

Roel This is not possible to reproduce after MDEV-25114 and when I moved wsrep_assert_no_bf_bf_wait as debug builds only.

Comment by Roel Van de Paar [ 2022-03-16 ]

jplindst Thank you!

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