[MDEV-24896] galera_sr.galera-features#56 MTR failed: query 'reap' failed: 1213: Deadlock found when trying to get lock Created: 2021-02-16  Updated: 2022-10-03  Resolved: 2022-05-04

Status: Closed
Project: MariaDB Server
Component/s: Galera, Tests
Affects Version/s: 10.4.18
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Stepan Patryshev (Inactive) Assignee: Jan Lindström (Inactive)
Resolution: Cannot Reproduce Votes: 0
Labels: None
Environment:

kvm-zyp-opensuse150-amd64


Attachments: Zip Archive 210128_galera-features#56_104_CS.zip     HTML File 210128_stdio_104_CS.html    

 Description   

galera_sr.galera-features#56 failed on BB 10.4 CS: "query 'reap' failed: 1213: Deadlock found when trying to get lock".
It seems to be a sporadic issue.

stdio.log:

10.4.18, 542d769ea1a22a7a6a87c9fe76ff911a162ade44, kvm-zyp-opensuse150-amd64

galera_sr.galera-features#56 'innodb'    w2 [ fail ]
        Test ended at 2021-01-28 08:45:33
 
CURRENT_TEST: galera_sr.galera-features#56
mysqltest: At line 50: query 'reap' failed: 1213: Deadlock found when trying to get lock; try restarting transaction
 
The result from queries just before the failure was:
< snip >
connection node_2;
set session wsrep_sync_wait=15;
SELECT COUNT(*) from ten;
COUNT(*)
10
SELECT COUNT(*) from t1;
COUNT(*)
0
set session wsrep_sync_wait=0;
SET GLOBAL wsrep_slave_threads = 4;
SET SESSION wsrep_trx_fragment_size = 1;
connection node_1;
INSERT INTO t1 (f2) SELECT 1 FROM ten AS a1, ten AS a2;;
connection node_1a;
INSERT INTO t1 (f2) SELECT 1 FROM ten AS a1, ten AS a2;;
connection node_2;
INSERT INTO t1 (f2) SELECT 1 FROM ten AS a1, ten AS a2;;
connection node_1;
connection node_1a;
connection node_2;
 
More results from queries before failure can be found in /dev/shm/var/2/log/galera-features#56.log
 
 - saving '/dev/shm/var/2/log/galera_sr.galera-features#56-innodb/' to '/dev/shm/var/log/galera_sr.galera-features#56-innodb/'
 
Retrying test galera_sr.galera-features#56, attempt(2/3)...
 
worker[2] > Restart  - not started
worker[2] > Restart  - not started
***Warnings generated in error logs during shutdown after running tests: galera_sr.GCF-900 galera_sr.GCF-561 galera_sr.GCF-1051 galera_sr.GCF-585 galera_sr.GCF-1008 galera_sr.GCF-627 galera_sr.MDEV-23623 galera_sr.GCF-1018 galera_sr.MDEV-22616 galera_sr.GCF-597 galera_sr.GCF-845 galera_sr.GCF-851 galera_sr.GCF-571 galera_sr.GCF-623 galera_sr.GCF-867 galera_sr.GCF-889 galera_sr.GCF-620 galera_sr.GCF-580 galera_sr.GCF-572 galera_sr.galera-features#56
 
2021-01-28  8:45:31 189 [Warning] WSREP: Could not find streaming applier for 0c336610-6145-11eb-b755-c63927cc0979:1476
2021-01-28  8:45:31 2 [ERROR] WSREP: Failed to apply write set: gtid: 0bf48c4d-6145-11eb-8658-435dcb31e7f0:562 server_id: 0c336610-6145-11eb-b755-c63927cc0979 client_id: 18446744073709551615 trx_id: 1476 flags: 20 (rollback | pa_unsafe)

Server logs.



 Comments   
Comment by Marko Mäkelä [ 2021-03-19 ]

I got a crash locally, on 10.4:

Server [mysqld.2 - pid: 847111, winpid: 847111, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2021-03-19 11:22:23 20 [Note] WSREP: Starting applier thread 20
2021-03-19 11:22:23 21 [Note] WSREP: Starting applier thread 21
2021-03-19 11:22:23 22 [Note] WSREP: Starting applier thread 22
mysqld: /mariadb/10.4/wsrep-lib/src/server_state.cpp:1265: void wsrep::server_state::stop_streaming_applier(const wsrep::id &, const wsrep::transaction_id &): Assertion `i != streaming_appliers_.end()' failed.
#4  0x000055993457394f in wsrep::transaction::after_applying (this=0x7fedbc006f60) at /mariadb/10.4/wsrep-lib/src/transaction.cpp:907
#5  0x000055993456ceb1 in rollback_fragment (server_state=@0x5599369a3f20: {_vptr$server_state = 0x559934d8f160 <vtable for Wsrep_server_state+16>, mutex_ = @0x5599369a41d0, cond_ = @0x5599369a41e0, server_service_ = @0x5599369a41f0, encryption_service_ = 0x0, state_ = wsrep::server_state::s_synced, state_hist_ = std::vector of length 6, capacity 8 = {wsrep::server_state::s_disconnected, wsrep::server_state::s_connected, wsrep::server_state::s_joiner, wsrep::server_state::s_initializing, wsrep::server_state::s_initialized, wsrep::server_state::s_joined}, state_waiters_ = std::vector of length 9, capacity 9 = {0, 0, 0, 0, 0, 0, 0, 0, 0}, bootstrap_ = false, initial_position_ = {id_ = {data_ = {buf = '\000' <repeats 15 times>}}, seqno_ = {seqno_ = -1}}, init_initialized_ = true, init_synced_ = true, sst_gtid_ = {id_ = {data_ = {buf = '\000' <repeats 15 times>}}, seqno_ = {seqno_ = -1}}, desync_count_ = 0, desynced_on_pause_ = false, pause_count_ = 0, pause_seqno_ = {seqno_ = -1}, streaming_clients_ = std::map with 0 elements, streaming_appliers_ = std::map with 2 elements = {[{first = {data_ = {buf = "\222\033<\016\210\224\021\353\261P\022\333\002\261\262M"}}, second = {id_ = 98}}] = 0x7fedbc028090, [{first = {data_ = {buf = "\222\033<\016\210\224\021\353\261P\022\333\002\261\262M"}}, second = {id_ = 99}}] = 0x7fedb402b180}, streaming_appliers_recovered_ = true, provider_ = 0x559936973e00, name_ = "jyty", id_ = {data_ = {buf = "\225\251\217\224\210\224\021\353\214\f\202\071\356\223\331\352"}}, incoming_address_ = "127.0.0.1:16241", address_ = "127.0.0.1", working_dir_ = "/dev/shm/10.4/mysql-test/var/12/mysqld.2/data/", encryption_key_ = std::vector of length 0, capacity 0, max_protocol_version_ = 4, rollback_mode_ = wsrep::server_state::rm_sync, connected_gtid_ = {id_ = {data_ = {buf = "\222\033f\302\210\224\021\353\217\251\242@T\003D."}}, seqno_ = {seqno_ = 2}}, previous_primary_view_ = {state_id_ = {id_ = {data_ = {buf = '\000' <repeats 15 times>}}, seqno_ = {seqno_ = -1}}, view_seqno_ = {seqno_ = -1}, status_ = wsrep::view::disconnected, capabilities_ = 0, own_index_ = -1, protocol_version_ = 0, members_ = std::vector of length 0, capacity 0}, current_view_ = {state_id_ = {id_ = {data_ = {buf = "\222\033f\302\210\224\021\353\217\251\242@T\003D."}}, seqno_ = {seqno_ = 2}}, view_seqno_ = {seqno_ = 2}, status_ = wsrep::view::primary, capabilities_ = 184703, own_index_ = 1, protocol_version_ = 4, members_ = std::vector of length 2, capacity 2 = {{id_ = {data_ = {buf = "\222\033<\016\210\224\021\353\261P\022\333\002\261\262M"}}, name_ = "jyty", incoming_ = "127.0.0.1:16240"}, {id_ = {data_ = {buf = "\225\251\217\224\210\224\021\353\214\f\202\071\356\223\331\352"}}, name_ = "jyty", incoming_ = "127.0.0.1:16241"}}}, last_committed_gtid_ = {id_ = {data_ = {buf = '\000' <repeats 15 times>}}, seqno_ = {seqno_ = -1}}}, high_priority_service=@0x7feddc300d30: {_vptr$high_priority_service = 0x559934ca0b00 <vtable for Wsrep_applier_service+16>, server_state_ = @0x5599369a3f20, must_exit_ = false}, streaming_applier=0x7fed5000c220, ws_handle=@0x7feddc2fff20: {transaction_id_ = {id_ = 89}, opaque_ = 0x7fedb403be60}, ws_meta=@0x7feddc3000d0: {gtid_ = {id_ = {data_ = {buf = "\222\033f\302\210\224\021\353\217\251\242@T\003D."}}, seqno_ = {seqno_ = 247}}, stid_ = {server_id_ = {data_ = {buf = "\225\251\217\224\210\224\021\353\214\f\202\071\356\223\331\352"}}, transaction_id_ = {id_ = 89}, client_id_ = {id_ = 18446744073709551615}}, depends_on_ = {seqno_ = 246}, flags_ = 20}) at /mariadb/10.4/wsrep-lib/src/server_state.cpp:254
#6  apply_write_set (server_state=<optimized out>, high_priority_service=@0x7feddc300d30: {_vptr$high_priority_service = 0x559934ca0b00 <vtable for Wsrep_applier_service+16>, server_state_ = @0x5599369a3f20, must_exit_ = false}, ws_handle=<optimized out>, ws_meta=@0x7feddc3000d0: {gtid_ = {id_ = {data_ = {buf = "\222\033f\302\210\224\021\353\217\251\242@T\003D."}}, seqno_ = {seqno_ = 247}}, stid_ = {server_id_ = {data_ = {buf = "\225\251\217\224\210\224\021\353\214\f\202\071\356\223\331\352"}}, transaction_id_ = {id_ = 89}, client_id_ = {id_ = 18446744073709551615}}, depends_on_ = {seqno_ = 246}, flags_ = 20}, data=<optimized out>) at /mariadb/10.4/wsrep-lib/src/server_state.cpp:312
#7  wsrep::server_state::on_apply (this=<optimized out>, high_priority_service=@0x7feddc300d30: {_vptr$high_priority_service = 0x559934ca0b00 <vtable for Wsrep_applier_service+16>, server_state_ = @0x5599369a3f20, must_exit_ = false}, ws_handle=<optimized out>, ws_meta=@0x7feddc3000d0: {gtid_ = {id_ = {data_ = {buf = "\222\033f\302\210\224\021\353\217\251\242@T\003D."}}, seqno_ = {seqno_ = 247}}, stid_ = {server_id_ = {data_ = {buf = "\225\251\217\224\210\224\021\353\214\f\202\071\356\223\331\352"}}, transaction_id_ = {id_ = 89}, client_id_ = {id_ = 18446744073709551615}}, depends_on_ = {seqno_ = 246}, flags_ = 20}, data=<optimized out>) at /mariadb/10.4/wsrep-lib/src/server_state.cpp:1136
#8  0x0000559934577a63 in wsrep::high_priority_service::apply (this=0x7feddc300d30, ws_handle=@0x7feddc2fff20: {transaction_id_ = {id_ = 89}, opaque_ = 0x7fedb403be60}, ws_meta=@0x7feddc3000d0: {gtid_ = {id_ = {data_ = {buf = "\222\033f\302\210\224\021\353\217\251\242@T\003D."}}, seqno_ = {seqno_ = 247}}, stid_ = {server_id_ = {data_ = {buf = "\225\251\217\224\210\224\021\353\214\f\202\071\356\223\331\352"}}, transaction_id_ = {id_ = 89}, client_id_ = {id_ = 18446744073709551615}}, depends_on_ = {seqno_ = 246}, flags_ = 20}, data=@0x7feddc2fff30: {ptr_ = 0x0, size_ = 0}) at /mariadb/10.4/wsrep-lib/include/wsrep/high_priority_service.hpp:47
#9  (anonymous namespace)::apply_cb (ctx=0x7feddc300d30, wsh=<optimized out>, flags=<optimized out>, buf=<optimized out>, meta=<optimized out>, exit_loop=0x7feddc3003df) at /mariadb/10.4/wsrep-lib/src/wsrep_provider_v26.cpp:502
#10 0x00007feddc526196 in ?? () from /usr/lib/galera/libgalera_smm.so
#11 0x00007feddc535203 in ?? () from /usr/lib/galera/libgalera_smm.so
#12 0x00007feddc53ba55 in ?? () from /usr/lib/galera/libgalera_smm.so
#13 0x00007feddc5652a8 in ?? () from /usr/lib/galera/libgalera_smm.so
#14 0x00007feddc565fd7 in ?? () from /usr/lib/galera/libgalera_smm.so
#15 0x00007feddc53c3c8 in ?? () from /usr/lib/galera/libgalera_smm.so
#16 0x00005599345780c8 in wsrep::wsrep_provider_v26::run_applier (this=<optimized out>, applier_ctx=0x7feddc2ff9f0) at /mariadb/10.4/wsrep-lib/src/wsrep_provider_v26.cpp:743
#17 0x0000559933d074c9 in wsrep_replication_process (thd=0x7fedbc000d28, arg=<optimized out>) at /mariadb/10.4/sql/wsrep_thd.cc:57
#18 0x0000559933cfe3ae in start_wsrep_THD (arg=arg@entry=0x559936a41aa0) at /mariadb/10.4/sql/wsrep_mysqld.cc:2847
#19 0x00005599344aa016 in pfs_spawn_thread (arg=0x559936a3aa58) at /mariadb/10.4/storage/perfschema/pfs.cc:1869
#20 0x00007fede1fecea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
#21 0x00007fede163edef in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Thread 35 (Thread 0x7fedc5b57700 (LWP 853751)):
#0  __lll_lock_wait (futex=futex@entry=0x559934e8b5b8 <LOCK_wsrep_server_state+40>, private=0) at lowlevellock.c:52
#1  0x00007fede1fef9d5 in __GI___pthread_mutex_lock (mutex=0x559934e8b5b8 <LOCK_wsrep_server_state+40>) at ../nptl/pthread_mutex_lock.c:135
#2  0x0000559934508f7c in safe_mutex_lock (mp=0x559934e8b590 <LOCK_wsrep_server_state>, my_flags=0, file=0x55993459dfa8 "/mariadb/10.4/sql/wsrep_mutex.h", line=34) at /mariadb/10.4/mysys/thr_mutex.c:293
#3  0x000055993456d412 in std::unique_lock<wsrep::mutex>::lock (this=<optimized out>) at /usr/bin/../lib/gcc/x86_64-linux-gnu/10/../../../../include/c++/10/bits/unique_lock.h:138
#4  std::unique_lock<wsrep::mutex>::unique_lock (this=<optimized out>, __m=@0x5599369a41d0: {_vptr$mutex = 0x559934c7f180 <vtable for Wsrep_mutex+16>}) at /usr/bin/../lib/gcc/x86_64-linux-gnu/10/../../../../include/c++/10/bits/unique_lock.h:68
#5  wsrep::server_state::start_streaming_client (this=0x5599369a3f20, client_state=0x7fedac011848) at /mariadb/10.4/wsrep-lib/src/server_state.cpp:1144
#6  0x0000559934574a57 in wsrep::transaction::certify_fragment (this=this@entry=0x7fedac0118b0, lock=@0x7fedc5b54f90: {_M_device = 0x7fedac011810, _M_owns = false}) at /mariadb/10.4/wsrep-lib/src/transaction.cpp:1460
#7  0x000055993457025c in wsrep::transaction::streaming_step (this=this@entry=0x7fedac0118b0, lock=@0x7fedc5b54f90: {_M_device = 0x7fedac011810, _M_owns = false}, force=false) at /mariadb/10.4/wsrep-lib/src/transaction.cpp:1391
#8  0x000055993457006f in wsrep::transaction::after_row (this=0x7fedac0118b0) at /mariadb/10.4/wsrep-lib/src/transaction.cpp:265
#9  0x0000559933db8095 in wsrep::client_state::after_row (this=<optimized out>) at /mariadb/10.4/wsrep-lib/include/wsrep/client_state.hpp:400
#10 wsrep_after_row (thd=<optimized out>) at /mariadb/10.4/sql/wsrep_trans_observer.h:172
#11 wsrep_after_row (thd=<optimized out>) at /mariadb/10.4/sql/handler.cc:6566
#12 0x0000559933db7fca in handler::ha_write_row (this=0x7fedac0d55a0, buf=0x7fedac1b3bd8 "\375\240\001") at /mariadb/10.4/sql/handler.cc:6765
#13 0x0000559933b0433f in write_record (thd=0x7fedac00b678, table=table@entry=0x7fedac1bb928, info=info@entry=0x7fedac1963d0) at /mariadb/10.4/sql/sql_insert.cc:2060
#14 0x0000559933b0a89d in select_insert::send_data (this=0x7fedac196388, values=<optimized out>) at /mariadb/10.4/sql/sql_insert.cc:3956
#15 0x0000559933b87779 in end_send (join=0x7fedac196438, join_tab=0x7fedac18be60, end_of_records=<optimized out>) at /mariadb/10.4/sql/sql_select.cc:21689
#16 0x0000559933c8462a in JOIN_CACHE::generate_full_extensions (this=this@entry=0x7fedac1981c8, rec_ptr=rec_ptr@entry=0x7fedac1b7558 "\245\245\245\245\245\245\245\245") at /mariadb/10.4/sql/sql_join_cache.cc:2472
#17 0x0000559933c84537 in JOIN_CACHE::join_matching_records (this=0x7fedac1981c8, skip_last=<optimized out>) at /mariadb/10.4/sql/sql_join_cache.cc:2364
#18 0x0000559933c8418e in JOIN_CACHE::join_records (this=0x7fedac1981c8, skip_last=false) at /mariadb/10.4/sql/sql_join_cache.cc:2147
#19 0x0000559933ba2d45 in sub_select_cache (join=0x7fedac196438, join_tab=0x7fedac18bab8, end_of_records=true) at /mariadb/10.4/sql/sql_select.cc:20278
#20 0x0000559933b8c280 in do_select (join=0x7fedac196438, procedure=<optimized out>) at /mariadb/10.4/sql/sql_select.cc:20040
#21 JOIN::exec_inner (this=this@entry=0x7fedac196438) at /mariadb/10.4/sql/sql_select.cc:4487
#22 0x0000559933b8b4fa in JOIN::exec (this=this@entry=0x7fedac196438) at /mariadb/10.4/sql/sql_select.cc:4269
#23 0x0000559933b6c8b9 in mysql_select (thd=thd@entry=0x7fedac00b678, tables=<optimized out>, wild_num=<optimized out>, fields=<optimized out>, conds=<optimized out>, og_num=<optimized out>, order=<optimized out>, group=<optimized out>, having=<optimized out>, proc_param=<optimized out>, select_options=<optimized out>, result=<optimized out>, unit=<optimized out>, select_lex=<optimized out>) at /mariadb/10.4/sql/sql_select.cc:4707
#24 0x0000559933b6c5bf in handle_select (thd=thd@entry=0x7fedac00b678, lex=lex@entry=0x7fedac00f4f0, result=result@entry=0x7fedac196388, setup_tables_done_option=<optimized out>, setup_tables_done_option@entry=1073741824) at /mariadb/10.4/sql/sql_select.cc:410
#25 0x0000559933b435b5 in mysql_execute_command (thd=thd@entry=0x7fedac00b678) at /mariadb/10.4/sql/sql_parse.cc:4711
#26 0x0000559933b37e64 in mysql_parse (thd=thd@entry=0x7fedac00b678, rawbuf=rawbuf@entry=0x7fedac0151d0 "INSERT INTO t1 (f2) SELECT 1 FROM ten AS a1, ten AS a2", length=<optimized out>, length@entry=54, parser_state=<optimized out>, parser_state@entry=0x7fedc5b56690, is_com_multi=false, is_next_command=<optimized out>) at /mariadb/10.4/sql/sql_parse.cc:7989
#27 0x0000559933b3939b in wsrep_mysql_parse (thd=thd@entry=0x7fedac00b678, rawbuf=0x7fedac0151d0 "INSERT INTO t1 (f2) SELECT 1 FROM ten AS a1, ten AS a2", length=54, parser_state=parser_state@entry=0x7fedc5b56690, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /mariadb/10.4/sql/sql_parse.cc:7793
#28 0x0000559933b3712e in dispatch_command (command=<optimized out>, command@entry=COM_QUERY, thd=thd@entry=0x7fedac00b678, packet=0x7fedac0151d0 "INSERT INTO t1 (f2) SELECT 1 FROM ten AS a1, ten AS a2", packet@entry=0x7fedac1852b9 "INSERT INTO t1 (f2) SELECT 1 FROM ten AS a1, ten AS a2;", packet_length=packet_length@entry=55, is_com_multi=false, is_next_command=false) at /mariadb/10.4/sql/sql_parse.cc:1841
#29 0x0000559933b3846d in do_command (thd=0x7fedac00b678) at /mariadb/10.4/sql/sql_parse.cc:1373
#30 0x0000559933c55549 in do_handle_one_connection (connect=connect@entry=0x559936e92e48) at /mariadb/10.4/sql/sql_connect.cc:1412
#31 0x0000559933c55383 in handle_one_connection (arg=arg@entry=0x559936e92e48) at /mariadb/10.4/sql/sql_connect.cc:1316
#32 0x00005599344aa016 in pfs_spawn_thread (arg=0x559936ec6288) at /mariadb/10.4/storage/perfschema/pfs.cc:1869
#33 0x00007fede1fecea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
#34 0x00007fede163edef in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

I will disable the test.

Comment by Jan Lindström (Inactive) [ 2022-05-04 ]

Could not reproduce with 10.4.25+26.4.11

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