[MDEV-22370] safe_mutex: Trying to lock uninitialized mutex at /data/src/10.4-bug/sql/rpl_parallel.cc, line 470 upon shutdown during FTWRL - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.4(EOL), 10.5
Fix Version/s: 10.5.4, 10.4.14
Component/s: Locking
Labels:
- sprint-week-18

Description

10.5 87a7968c
2020-04-14 10:14:49 0 [Note] /ten1/builds/10.5-87a7968c-deb/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
2020-04-14 10:14:49 0 [Note] Event Scheduler: Purging the queue. 14 events
safe_mutex: Trying to lock uninitialized mutex at /home/elenst/src/10.5/sql/rpl_parallel.cc, line 470
200414 10:14:49 [ERROR] mysqld got signal 6 ;

#3 <signal handler called>
#4 0x00007f73a1ad5207 in raise () from /lib64/libc.so.6
#5 0x00007f73a1ad68f8 in abort () from /lib64/libc.so.6
#6 0x0000560ad0f8b4cf in safe_mutex_lock (mp=0x560ad1f58d90 <global_rpl_thread_pool+16>, my_flags=0, file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", line=470) at /home/elenst/src/10.5/mysys/thr_mutex.c:244
#7 0x0000560ad05107d1 in inline_mysql_mutex_lock (that=0x560ad1f58d90 <global_rpl_thread_pool+16>, src_file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", src_line=470) at /home/elenst/src/10.5/include/mysql/psi/mysql_thread.h:763
#8 0x0000560ad051229d in pool_mark_busy (pool=0x560ad1f58d80 <global_rpl_thread_pool>, thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:470
#9 0x0000560ad05126f2 in rpl_pause_for_ftwrl (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:563
#10 0x0000560ad02eb534 in mysql_execute_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5374
#11 0x0000560ad02f3912 in mysql_parse (thd=0x7f7328000b18, rawbuf=0x7f7328012460 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", length=51, parser_state=0x7f7384acf520, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:7953
#12 0x0000560ad02df2c0 in dispatch_command (command=COM_QUERY, thd=0x7f7328000b18, packet=0x7f7328008809 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", packet_length=51, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:1840
#13 0x0000560ad02dd93c in do_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:1359
#14 0x0000560ad0483c6d in do_handle_one_connection (connect=0x560ad51db8f8, put_in_cache=true) at /home/elenst/src/10.5/sql/sql_connect.cc:1422
#15 0x0000560ad0483986 in handle_one_connection (arg=0x560ad51db8f8) at /home/elenst/src/10.5/sql/sql_connect.cc:1319
#16 0x0000560ad09c173e in pfs_spawn_thread (arg=0x560ad52f7448) at /home/elenst/src/10.5/storage/perfschema/pfs.cc:2201
#17 0x00007f73a310bdd5 in start_thread () from /lib64/libpthread.so.0
#18 0x00007f73a1b9cead in clone () from /lib64/libc.so.6

The stack trace above is from an original failure in concurrent tests.

The test case below will produce a failure with line numbers in rpl_parallel.cc shifted by 1, due to the suggested debug injection.
Theoretically it can fail without the injection, but chances are slim, while with it it fails for me every time.

injection
index 9344312fe62..e42e6b2ebb5 100644
--- a/sql/rpl_parallel.cc
+++ b/sql/rpl_parallel.cc
@@ -467,6 +467,7 @@ pool_mark_busy(rpl_parallel_thread_pool pool, THD thd)
So we protect the infrequent operations of FLUSH TABLES WITH READ LOCK and
pool size changes with this condition wait.
*/
+ DBUG_EXECUTE_IF("sleep_mark_busy",my_sleep(1000000););
mysql_mutex_lock(&pool->LOCK_rpl_thread_pool);
if (thd)
{

Test case
--connect (con1,localhost,root,,)
SET DEBUG_DBUG='+d,sleep_mark_busy';
--send
FLUSH TABLES WITH READ LOCK;

--connection default
--source include/restart_mysqld.inc

Reproducible on 10.4, 10.5.
Could not reproduce and didn't observe on 10.3.
I have no information if the problem has any effect on non-debug builds.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

error22_all_threads
58 kB
2020-04-27 11:10

Issue Links

relates to

MDEV-14656 safe_mutex: Trying to lock uninitialized mutex or Got error 22 when trying to lock mutex LOCK_event_queue at sql/event_queue.cc, line 716 upon DROP DATABASE / EVENT upon server shutdown

Open

Activity

Ascending order - Click to sort in descending order

Elena Stepanova created issue - 2020-04-26 12:41

Elena Stepanova made changes - 2020-04-26 12:42

Field	Original Value	New Value
Description	{noformat:title=10.5 87a7968c} 2020-04-14 10:14:49 0 [Note] /ten1/builds/10.5-87a7968c-deb/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown 2020-04-14 10:14:49 0 [Note] Event Scheduler: Purging the queue. 14 events safe_mutex: Trying to lock uninitialized mutex at /home/elenst/src/10.5/sql/rpl_parallel.cc, line 470 200414 10:14:49 [ERROR] mysqld got signal 6 ; #3 <signal handler called> #4 0x00007fcc5eb2d207 in raise () from /lib64/libc.so.6 #5 0x00007fcc5eb2e8f8 in abort () from /lib64/libc.so.6 #6 0x0000556aa49cd474 in safe_mutex_lock (mp=0x556aa599ad90 <global_rpl_thread_pool+16>, my_flags=0, file=0x556aa4bed060 "/home/elenst/src/10.5/sql/rpl_parallel.cc", line=500) at /home/elenst/src/10.5/mysys/thr_mutex.c:297 #7 0x0000556aa3f523e3 in inline_mysql_mutex_lock (that=0x556aa599ad90 <global_rpl_thread_pool+16>, src_file=0x556aa4bed060 "/home/elenst/src/10.5/sql/rpl_parallel.cc", src_line=500) at /home/elenst/src/10.5/include/mysql/psi/mysql_thread.h:763 #8 0x0000556aa3f54016 in pool_mark_not_busy (pool=0x556aa599ad80 <global_rpl_thread_pool>) at /home/elenst/src/10.5/sql/rpl_parallel.cc:500 #9 0x0000556aa3f54280 in rpl_unpause_after_ftwrl (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:537 #10 0x0000556aa3d2cbb0 in mysql_execute_command (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5433 #11 0x0000556aa3c3020d in sp_instr_stmt::exec_core (this=0x7fcbe80ad7f0, thd=0x7fcbe8000b18, nextp=0x7fcc49123014) at /home/elenst/src/10.5/sql/sp_head.cc:3761 #12 0x0000556aa3c2f559 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fcbe80ad838, thd=0x7fcbe8000b18, nextp=0x7fcc49123014, open_tables=false, instr=0x7fcbe80ad7f0) at /home/elenst/src/10.5/sql/sp_head.cc:3488 #13 0x0000556aa3c2fd85 in sp_instr_stmt::execute (this=0x7fcbe80ad7f0, thd=0x7fcbe8000b18, nextp=0x7fcc49123014) at /home/elenst/src/10.5/sql/sp_head.cc:3667 #14 0x0000556aa3c29460 in sp_head::execute (this=0x7fcbe80ac920, thd=0x7fcbe8000b18, merge_da_on_success=true) at /home/elenst/src/10.5/sql/sp_head.cc:1432 #15 0x0000556aa3c2c25d in sp_head::execute_procedure (this=0x7fcbe80ac920, thd=0x7fcbe8000b18, args=0x7fcbe80059f0) at /home/elenst/src/10.5/sql/sp_head.cc:2442 #16 0x0000556aa3d23c9e in do_execute_sp (thd=0x7fcbe8000b18, sp=0x7fcbe80ac920) at /home/elenst/src/10.5/sql/sql_parse.cc:3013 #17 0x0000556aa3d2493c in Sql_cmd_call::execute (this=0x7fcbe8012670, thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:3258 #18 0x0000556aa3d2eaed in mysql_execute_command (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5912 #19 0x0000556aa3d34cda in mysql_parse (thd=0x7fcbe8000b18, rawbuf=0x7fcbe8012580 "CALL /* QNO 669 CON_ID 9 / sp_grammar3", length=39, parser_state=0x7fcc49124520, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:7957 #20 0x0000556aa3d2062c in dispatch_command (command=COM_QUERY, thd=0x7fcbe8000b18, packet=0x7fcbe8008699 "CALL / QNO 669 CON_ID 9 / sp_grammar3", packet_length=39, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:1840 #21 0x0000556aa3d1eca8 in do_command (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:1359 #22 0x0000556aa3ec5479 in do_handle_one_connection (connect=0x556aa9a08da8, put_in_cache=true) at /home/elenst/src/10.5/sql/sql_connect.cc:1422 #23 0x0000556aa3ec5192 in handle_one_connection (arg=0x556aa9a08da8) at /home/elenst/src/10.5/sql/sql_connect.cc:1319 #24 0x0000556aa440384c in pfs_spawn_thread (arg=0x556aa9988cd8) at /home/elenst/src/10.5/storage/perfschema/pfs.cc:2201 #25 0x00007fcc60163dd5 in start_thread () from /lib64/libpthread.so.0 #26 0x00007fcc5ebf4ead in clone () from /lib64/libc.so.6 {noformat} The stack trace above is from an original failure in concurrent tests. The test case below will produce a failure with line numbers in rpl_parallel.cc shifted by 1, due to the suggested debug injection. Theoretically it can fail without the injection, but chances are slim, while with it it fails for me every time. {noformat:title=injection} index 9344312fe62..e42e6b2ebb5 100644 --- a/sql/rpl_parallel.cc +++ b/sql/rpl_parallel.cc @@ -467,6 +467,7 @@ pool_mark_busy(rpl_parallel_thread_pool pool, THD thd) So we protect the infrequent operations of FLUSH TABLES WITH READ LOCK and pool size changes with this condition wait. / + DBUG_EXECUTE_IF("sleep_mark_busy",my_sleep(1000000);); mysql_mutex_lock(&pool->LOCK_rpl_thread_pool); if (thd) { {noformat} {code:sql\|title=Test case} --connect (con1,localhost,root,,) SET DEBUG_DBUG='+d,sleep_mark_busy'; --send FLUSH TABLES WITH READ LOCK; --connection default --source include/restart_mysqld.inc {code} Reproducible on 10.4, 10.5. Could not reproduce and didn't observe on 10.3. I have no information if the problem has any effect on non-debug builds.	{noformat:title=10.5 87a7968c} 2020-04-14 10:14:49 0 [Note] /ten1/builds/10.5-87a7968c-deb/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown 2020-04-14 10:14:49 0 [Note] Event Scheduler: Purging the queue. 14 events safe_mutex: Trying to lock uninitialized mutex at /home/elenst/src/10.5/sql/rpl_parallel.cc, line 470 200414 10:14:49 [ERROR] mysqld got signal 6 ; #3 <signal handler called> #4 0x00007fcc5eb2d207 in raise () from /lib64/libc.so.6 #5 0x00007fcc5eb2e8f8 in abort () from /lib64/libc.so.6 #6 0x0000556aa49cd474 in safe_mutex_lock (mp=0x556aa599ad90 <global_rpl_thread_pool+16>, my_flags=0, file=0x556aa4bed060 "/home/elenst/src/10.5/sql/rpl_parallel.cc", line=500) at /home/elenst/src/10.5/mysys/thr_mutex.c:297 #7 0x0000556aa3f523e3 in inline_mysql_mutex_lock (that=0x556aa599ad90 <global_rpl_thread_pool+16>, src_file=0x556aa4bed060 "/home/elenst/src/10.5/sql/rpl_parallel.cc", src_line=500) at /home/elenst/src/10.5/include/mysql/psi/mysql_thread.h:763 #8 0x0000556aa3f54016 in pool_mark_not_busy (pool=0x556aa599ad80 <global_rpl_thread_pool>) at /home/elenst/src/10.5/sql/rpl_parallel.cc:500 #9 0x0000556aa3f54280 in rpl_unpause_after_ftwrl (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:537 #10 0x0000556aa3d2cbb0 in mysql_execute_command (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5433 #11 0x0000556aa3c3020d in sp_instr_stmt::exec_core (this=0x7fcbe80ad7f0, thd=0x7fcbe8000b18, nextp=0x7fcc49123014) at /home/elenst/src/10.5/sql/sp_head.cc:3761 #12 0x0000556aa3c2f559 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fcbe80ad838, thd=0x7fcbe8000b18, nextp=0x7fcc49123014, open_tables=false, instr=0x7fcbe80ad7f0) at /home/elenst/src/10.5/sql/sp_head.cc:3488 #13 0x0000556aa3c2fd85 in sp_instr_stmt::execute (this=0x7fcbe80ad7f0, thd=0x7fcbe8000b18, nextp=0x7fcc49123014) at /home/elenst/src/10.5/sql/sp_head.cc:3667 #14 0x0000556aa3c29460 in sp_head::execute (this=0x7fcbe80ac920, thd=0x7fcbe8000b18, merge_da_on_success=true) at /home/elenst/src/10.5/sql/sp_head.cc:1432 #15 0x0000556aa3c2c25d in sp_head::execute_procedure (this=0x7fcbe80ac920, thd=0x7fcbe8000b18, args=0x7fcbe80059f0) at /home/elenst/src/10.5/sql/sp_head.cc:2442 #16 0x0000556aa3d23c9e in do_execute_sp (thd=0x7fcbe8000b18, sp=0x7fcbe80ac920) at /home/elenst/src/10.5/sql/sql_parse.cc:3013 #17 0x0000556aa3d2493c in Sql_cmd_call::execute (this=0x7fcbe8012670, thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:3258 #18 0x0000556aa3d2eaed in mysql_execute_command (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5912 #19 0x0000556aa3d34cda in mysql_parse (thd=0x7fcbe8000b18, rawbuf=0x7fcbe8012580 "CALL /* QNO 669 CON_ID 9 / sp_grammar3", length=39, parser_state=0x7fcc49124520, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:7957 #20 0x0000556aa3d2062c in dispatch_command (command=COM_QUERY, thd=0x7fcbe8000b18, packet=0x7fcbe8008699 "CALL / QNO 669 CON_ID 9 / sp_grammar3", packet_length=39, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:1840 #21 0x0000556aa3d1eca8 in do_command (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:1359 #22 0x0000556aa3ec5479 in do_handle_one_connection (connect=0x556aa9a08da8, put_in_cache=true) at /home/elenst/src/10.5/sql/sql_connect.cc:1422 #23 0x0000556aa3ec5192 in handle_one_connection (arg=0x556aa9a08da8) at /home/elenst/src/10.5/sql/sql_connect.cc:1319 #24 0x0000556aa440384c in pfs_spawn_thread (arg=0x556aa9988cd8) at /home/elenst/src/10.5/storage/perfschema/pfs.cc:2201 #25 0x00007fcc60163dd5 in start_thread () from /lib64/libpthread.so.0 #26 0x00007fcc5ebf4ead in clone () from /lib64/libc.so.6 {noformat} The stack trace above is from an original failure in concurrent tests. The test case below won't have the part related to stored procedures, and also will produce a failure with line numbers in rpl_parallel.cc shifted by 1, due to the suggested debug injection. Theoretically it can fail without the injection, but chances are slim, while with it it fails for me every time. {noformat:title=injection} index 9344312fe62..e42e6b2ebb5 100644 --- a/sql/rpl_parallel.cc +++ b/sql/rpl_parallel.cc @@ -467,6 +467,7 @@ pool_mark_busy(rpl_parallel_thread_pool pool, THD thd) So we protect the infrequent operations of FLUSH TABLES WITH READ LOCK and pool size changes with this condition wait. / + DBUG_EXECUTE_IF("sleep_mark_busy",my_sleep(1000000);); mysql_mutex_lock(&pool->LOCK_rpl_thread_pool); if (thd) { {noformat} {code:sql\|title=Test case} --connect (con1,localhost,root,,) SET DEBUG_DBUG='+d,sleep_mark_busy'; --send FLUSH TABLES WITH READ LOCK; --connection default --source include/restart_mysqld.inc {code} Reproducible on 10.4, 10.5. Could not reproduce and didn't observe on 10.3. I have no information if the problem has any effect on non-debug builds.

Elena Stepanova made changes - 2020-04-26 12:46

Description

{noformat:title=10.5 87a7968c}
2020-04-14 10:14:49 0 [Note] /ten1/builds/10.5-87a7968c-deb/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
2020-04-14 10:14:49 0 [Note] Event Scheduler: Purging the queue. 14 events
safe_mutex: Trying to lock uninitialized mutex at /home/elenst/src/10.5/sql/rpl_parallel.cc, line 470
200414 10:14:49 [ERROR] mysqld got signal 6 ;

#3 <signal handler called>
#4 0x00007fcc5eb2d207 in raise () from /lib64/libc.so.6
#5 0x00007fcc5eb2e8f8 in abort () from /lib64/libc.so.6
#6 0x0000556aa49cd474 in safe_mutex_lock (mp=0x556aa599ad90 <global_rpl_thread_pool+16>, my_flags=0, file=0x556aa4bed060 "/home/elenst/src/10.5/sql/rpl_parallel.cc", line=500) at /home/elenst/src/10.5/mysys/thr_mutex.c:297
#7 0x0000556aa3f523e3 in inline_mysql_mutex_lock (that=0x556aa599ad90 <global_rpl_thread_pool+16>, src_file=0x556aa4bed060 "/home/elenst/src/10.5/sql/rpl_parallel.cc", src_line=500) at /home/elenst/src/10.5/include/mysql/psi/mysql_thread.h:763
#8 0x0000556aa3f54016 in pool_mark_not_busy (pool=0x556aa599ad80 <global_rpl_thread_pool>) at /home/elenst/src/10.5/sql/rpl_parallel.cc:500
#9 0x0000556aa3f54280 in rpl_unpause_after_ftwrl (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:537
#10 0x0000556aa3d2cbb0 in mysql_execute_command (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5433
#11 0x0000556aa3c3020d in sp_instr_stmt::exec_core (this=0x7fcbe80ad7f0, thd=0x7fcbe8000b18, nextp=0x7fcc49123014) at /home/elenst/src/10.5/sql/sp_head.cc:3761
#12 0x0000556aa3c2f559 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fcbe80ad838, thd=0x7fcbe8000b18, nextp=0x7fcc49123014, open_tables=false, instr=0x7fcbe80ad7f0) at /home/elenst/src/10.5/sql/sp_head.cc:3488
#13 0x0000556aa3c2fd85 in sp_instr_stmt::execute (this=0x7fcbe80ad7f0, thd=0x7fcbe8000b18, nextp=0x7fcc49123014) at /home/elenst/src/10.5/sql/sp_head.cc:3667
#14 0x0000556aa3c29460 in sp_head::execute (this=0x7fcbe80ac920, thd=0x7fcbe8000b18, merge_da_on_success=true) at /home/elenst/src/10.5/sql/sp_head.cc:1432
#15 0x0000556aa3c2c25d in sp_head::execute_procedure (this=0x7fcbe80ac920, thd=0x7fcbe8000b18, args=0x7fcbe80059f0) at /home/elenst/src/10.5/sql/sp_head.cc:2442
#16 0x0000556aa3d23c9e in do_execute_sp (thd=0x7fcbe8000b18, sp=0x7fcbe80ac920) at /home/elenst/src/10.5/sql/sql_parse.cc:3013
#17 0x0000556aa3d2493c in Sql_cmd_call::execute (this=0x7fcbe8012670, thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:3258
#18 0x0000556aa3d2eaed in mysql_execute_command (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5912
#19 0x0000556aa3d34cda in mysql_parse (thd=0x7fcbe8000b18, rawbuf=0x7fcbe8012580 "CALL /* QNO 669 CON_ID 9 */ sp_grammar3", length=39, parser_state=0x7fcc49124520, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:7957
#20 0x0000556aa3d2062c in dispatch_command (command=COM_QUERY, thd=0x7fcbe8000b18, packet=0x7fcbe8008699 "CALL /* QNO 669 CON_ID 9 */ sp_grammar3", packet_length=39, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:1840
#21 0x0000556aa3d1eca8 in do_command (thd=0x7fcbe8000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:1359
#22 0x0000556aa3ec5479 in do_handle_one_connection (connect=0x556aa9a08da8, put_in_cache=true) at /home/elenst/src/10.5/sql/sql_connect.cc:1422
#23 0x0000556aa3ec5192 in handle_one_connection (arg=0x556aa9a08da8) at /home/elenst/src/10.5/sql/sql_connect.cc:1319
#24 0x0000556aa440384c in pfs_spawn_thread (arg=0x556aa9988cd8) at /home/elenst/src/10.5/storage/perfschema/pfs.cc:2201
#25 0x00007fcc60163dd5 in start_thread () from /lib64/libpthread.so.0
#26 0x00007fcc5ebf4ead in clone () from /lib64/libc.so.6
{noformat}

The stack trace above is from an original failure in concurrent tests.

The test case below won't have the part related to stored procedures, and also will produce a failure with line numbers in rpl_parallel.cc shifted by 1, due to the suggested debug injection.
Theoretically it can fail without the injection, but chances are slim, while with it it fails for me every time.

{noformat:title=injection}
index 9344312fe62..e42e6b2ebb5 100644
--- a/sql/rpl_parallel.cc
+++ b/sql/rpl_parallel.cc
@@ -467,6 +467,7 @@ pool_mark_busy(rpl_parallel_thread_pool *pool, THD *thd)
     So we protect the infrequent operations of FLUSH TABLES WITH READ LOCK and
     pool size changes with this condition wait.
   */
+ DBUG_EXECUTE_IF("sleep_mark_busy",my_sleep(1000000););
   mysql_mutex_lock(&pool->LOCK_rpl_thread_pool);
   if (thd)
   {
{noformat}
{code:sql|title=Test case}
--connect (con1,localhost,root,,)
SET DEBUG_DBUG='+d,sleep_mark_busy';
--send
  FLUSH TABLES WITH READ LOCK;

--connection default
--source include/restart_mysqld.inc
{code}

Reproducible on 10.4, 10.5.
Could not reproduce and didn't observe on 10.3.
I have no information if the problem has any effect on non-debug builds.

{noformat:title=10.5 87a7968c}
2020-04-14 10:14:49 0 [Note] /ten1/builds/10.5-87a7968c-deb/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
2020-04-14 10:14:49 0 [Note] Event Scheduler: Purging the queue. 14 events
safe_mutex: Trying to lock uninitialized mutex at /home/elenst/src/10.5/sql/rpl_parallel.cc, line 470
200414 10:14:49 [ERROR] mysqld got signal 6 ;

#3 <signal handler called>
#4 0x00007f73a1ad5207 in raise () from /lib64/libc.so.6
#5 0x00007f73a1ad68f8 in abort () from /lib64/libc.so.6
#6 0x0000560ad0f8b4cf in safe_mutex_lock (mp=0x560ad1f58d90 <global_rpl_thread_pool+16>, my_flags=0, file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", line=470) at /home/elenst/src/10.5/mysys/thr_mutex.c:244
#7 0x0000560ad05107d1 in inline_mysql_mutex_lock (that=0x560ad1f58d90 <global_rpl_thread_pool+16>, src_file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", src_line=470) at /home/elenst/src/10.5/include/mysql/psi/mysql_thread.h:763
#8 0x0000560ad051229d in pool_mark_busy (pool=0x560ad1f58d80 <global_rpl_thread_pool>, thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:470
#9 0x0000560ad05126f2 in rpl_pause_for_ftwrl (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:563
#10 0x0000560ad02eb534 in mysql_execute_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5374
#11 0x0000560ad02f3912 in mysql_parse (thd=0x7f7328000b18, rawbuf=0x7f7328012460 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", length=51, parser_state=0x7f7384acf520, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:7953
#12 0x0000560ad02df2c0 in dispatch_command (command=COM_QUERY, thd=0x7f7328000b18, packet=0x7f7328008809 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", packet_length=51, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:1840
#13 0x0000560ad02dd93c in do_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:1359
#14 0x0000560ad0483c6d in do_handle_one_connection (connect=0x560ad51db8f8, put_in_cache=true) at /home/elenst/src/10.5/sql/sql_connect.cc:1422
#15 0x0000560ad0483986 in handle_one_connection (arg=0x560ad51db8f8) at /home/elenst/src/10.5/sql/sql_connect.cc:1319
#16 0x0000560ad09c173e in pfs_spawn_thread (arg=0x560ad52f7448) at /home/elenst/src/10.5/storage/perfschema/pfs.cc:2201
#17 0x00007f73a310bdd5 in start_thread () from /lib64/libpthread.so.0
#18 0x00007f73a1b9cead in clone () from /lib64/libc.so.6
{noformat}

The stack trace above is from an original failure in concurrent tests.

The test case below will produce a failure with line numbers in rpl_parallel.cc shifted by 1, due to the suggested debug injection.
Theoretically it can fail without the injection, but chances are slim, while with it it fails for me every time.

{noformat:title=injection}
index 9344312fe62..e42e6b2ebb5 100644
--- a/sql/rpl_parallel.cc
+++ b/sql/rpl_parallel.cc
@@ -467,6 +467,7 @@ pool_mark_busy(rpl_parallel_thread_pool *pool, THD *thd)
     So we protect the infrequent operations of FLUSH TABLES WITH READ LOCK and
     pool size changes with this condition wait.
   */
+ DBUG_EXECUTE_IF("sleep_mark_busy",my_sleep(1000000););
   mysql_mutex_lock(&pool->LOCK_rpl_thread_pool);
   if (thd)
   {
{noformat}
{code:sql|title=Test case}
--connect (con1,localhost,root,,)
SET DEBUG_DBUG='+d,sleep_mark_busy';
--send
  FLUSH TABLES WITH READ LOCK;

--connection default
--source include/restart_mysqld.inc
{code}

Reproducible on 10.4, 10.5.
Could not reproduce and didn't observe on 10.3.
I have no information if the problem has any effect on non-debug builds.

Andrei Elkin made changes - 2020-04-27 08:36

Assignee

Andrei Elkin [ elkin ]

Sachin Setiya [ sachin.setiya.007 ]

Andrei Elkin made changes - 2020-04-27 08:51

Labels

sprint-week-18

Elena Stepanova made changes - 2020-04-27 11:10

Attachment

error22_all_threads [ 51455 ]

Elena Stepanova made changes - 2020-04-27 15:50

Link

This issue relates to MDEV-14656 [ MDEV-14656 ]

Sachin Setiya (Inactive) made changes - 2020-04-28 12:13

Description

{noformat:title=10.5 87a7968c}
2020-04-14 10:14:49 0 [Note] /ten1/builds/10.5-87a7968c-deb/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
2020-04-14 10:14:49 0 [Note] Event Scheduler: Purging the queue. 14 events
safe_mutex: Trying to lock uninitialized mutex at /home/elenst/src/10.5/sql/rpl_parallel.cc, line 470
200414 10:14:49 [ERROR] mysqld got signal 6 ;

#3 <signal handler called>
#4 0x00007f73a1ad5207 in raise () from /lib64/libc.so.6
#5 0x00007f73a1ad68f8 in abort () from /lib64/libc.so.6
#6 0x0000560ad0f8b4cf in safe_mutex_lock (mp=0x560ad1f58d90 <global_rpl_thread_pool+16>, my_flags=0, file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", line=470) at /home/elenst/src/10.5/mysys/thr_mutex.c:244
#7 0x0000560ad05107d1 in inline_mysql_mutex_lock (that=0x560ad1f58d90 <global_rpl_thread_pool+16>, src_file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", src_line=470) at /home/elenst/src/10.5/include/mysql/psi/mysql_thread.h:763
#8 0x0000560ad051229d in pool_mark_busy (pool=0x560ad1f58d80 <global_rpl_thread_pool>, thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:470
#9 0x0000560ad05126f2 in rpl_pause_for_ftwrl (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:563
#10 0x0000560ad02eb534 in mysql_execute_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5374
#11 0x0000560ad02f3912 in mysql_parse (thd=0x7f7328000b18, rawbuf=0x7f7328012460 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", length=51, parser_state=0x7f7384acf520, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:7953
#12 0x0000560ad02df2c0 in dispatch_command (command=COM_QUERY, thd=0x7f7328000b18, packet=0x7f7328008809 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", packet_length=51, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:1840
#13 0x0000560ad02dd93c in do_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:1359
#14 0x0000560ad0483c6d in do_handle_one_connection (connect=0x560ad51db8f8, put_in_cache=true) at /home/elenst/src/10.5/sql/sql_connect.cc:1422
#15 0x0000560ad0483986 in handle_one_connection (arg=0x560ad51db8f8) at /home/elenst/src/10.5/sql/sql_connect.cc:1319
#16 0x0000560ad09c173e in pfs_spawn_thread (arg=0x560ad52f7448) at /home/elenst/src/10.5/storage/perfschema/pfs.cc:2201
#17 0x00007f73a310bdd5 in start_thread () from /lib64/libpthread.so.0
#18 0x00007f73a1b9cead in clone () from /lib64/libc.so.6
{noformat}

The stack trace above is from an original failure in concurrent tests.

The test case below will produce a failure with line numbers in rpl_parallel.cc shifted by 1, due to the suggested debug injection.
Theoretically it can fail without the injection, but chances are slim, while with it it fails for me every time.

{noformat:title=injection}
index 9344312fe62..e42e6b2ebb5 100644
--- a/sql/rpl_parallel.cc
+++ b/sql/rpl_parallel.cc
@@ -467,6 +467,7 @@ pool_mark_busy(rpl_parallel_thread_pool *pool, THD *thd)
     So we protect the infrequent operations of FLUSH TABLES WITH READ LOCK and
     pool size changes with this condition wait.
   */
+ DBUG_EXECUTE_IF("sleep_mark_busy",my_sleep(1000000););
   mysql_mutex_lock(&pool->LOCK_rpl_thread_pool);
   if (thd)
   {
{noformat}
{code:sql|title=Test case}
--connect (con1,localhost,root,,)
SET DEBUG_DBUG='+d,sleep_mark_busy';
--send
  FLUSH TABLES WITH READ LOCK;

--connection default
--source include/restart_mysqld.inc
{code}

Reproducible on 10.4, 10.5.
Could not reproduce and didn't observe on 10.3.
I have no information if the problem has any effect on non-debug builds.

{noformat:title=10.5 87a7968c}
2020-04-14 10:14:49 0 [Note] /ten1/builds/10.5-87a7968c-deb/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
2020-04-14 10:14:49 0 [Note] Event Scheduler: Purging the queue. 14 events
safe_mutex: Trying to lock uninitialized mutex at /home/elenst/src/10.5/sql/rpl_parallel.cc, line 470
200414 10:14:49 [ERROR] mysqld got signal 6 ;

#3 <signal handler called>
#4 0x00007f73a1ad5207 in raise () from /lib64/libc.so.6
#5 0x00007f73a1ad68f8 in abort () from /lib64/libc.so.6
#6 0x0000560ad0f8b4cf in safe_mutex_lock (mp=0x560ad1f58d90 <global_rpl_thread_pool+16>, my_flags=0, file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", line=470) at /home/elenst/src/10.5/mysys/thr_mutex.c:244
#7 0x0000560ad05107d1 in inline_mysql_mutex_lock (that=0x560ad1f58d90 <global_rpl_thread_pool+16>, src_file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", src_line=470) at /home/elenst/src/10.5/include/mysql/psi/mysql_thread.h:763
#8 0x0000560ad051229d in pool_mark_busy (pool=0x560ad1f58d80 <global_rpl_thread_pool>, thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:470
#9 0x0000560ad05126f2 in rpl_pause_for_ftwrl (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:563
#10 0x0000560ad02eb534 in mysql_execute_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5374
#11 0x0000560ad02f3912 in mysql_parse (thd=0x7f7328000b18, rawbuf=0x7f7328012460 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", length=51, parser_state=0x7f7384acf520, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:7953
#12 0x0000560ad02df2c0 in dispatch_command (command=COM_QUERY, thd=0x7f7328000b18, packet=0x7f7328008809 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", packet_length=51, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:1840
#13 0x0000560ad02dd93c in do_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:1359
#14 0x0000560ad0483c6d in do_handle_one_connection (connect=0x560ad51db8f8, put_in_cache=true) at /home/elenst/src/10.5/sql/sql_connect.cc:1422
#15 0x0000560ad0483986 in handle_one_connection (arg=0x560ad51db8f8) at /home/elenst/src/10.5/sql/sql_connect.cc:1319
#16 0x0000560ad09c173e in pfs_spawn_thread (arg=0x560ad52f7448) at /home/elenst/src/10.5/storage/perfschema/pfs.cc:2201
#17 0x00007f73a310bdd5 in start_thread () from /lib64/libpthread.so.0
#18 0x00007f73a1b9cead in clone () from /lib64/libc.so.6
{noformat}

The stack trace above is from an original failure in concurrent tests.

The test case below will produce a failure with line numbers in rpl_parallel.cc shifted by 1, due to the suggested debug injection.
Theoretically it can fail without the injection, but chances are slim, while with it it fails for me every time.

{noformat:title=injection}
index 9344312fe62..e42e6b2ebb5 100644
--- a/sql/rpl_parallel.cc
+++ b/sql/rpl_parallel.cc
@@ -467,6 +467,7 @@ pool_mark_busy(rpl_parallel_thread_pool *pool, THD *thd)
     So we protect the infrequent operations of FLUSH TABLES WITH READ LOCK and
     pool size changes with this condition wait.
   */
+ DBUG_EXECUTE_IF("sleep_mark_busy",my_sleep(1000000););
   mysql_mutex_lock(&pool->LOCK_rpl_thread_pool);
   if (thd)
   {
{noformat}
{code:sql|title=Test case}
--connect (con1,localhost,root,,)
SET DEBUG_DBUG='+d,sleep_mark_busy';
--send
  FLUSH TABLES WITH READ LOCK;

--connection default
--source include/restart_mysqld.inc
{code}

Reproducible on 10.4, 10.5.
Could not reproduce and didn't observe on 10.3.
I have no information if the problem has any effect on non-debug builds.

This also fails (when we are on slave with pool>threads >0)

{noformat}
--source include/master-slave.inc

--connection master

--connection slave
stop slave;
SET GLOBAL slave_parallel_threads=10;
set global slave_parallel_mode=optimistic;
change master to master_use_gtid=slave_pos;
start slave;
--connect (con1,127.0.0.1,root,,test,$SLAVE_MYPORT)
SET DEBUG_DBUG='+d,sleep_mark_busy';
--send
  FLUSH TABLES WITH READ LOCK;

--connection slave
--source include/rpl_restart_server.inc

--connection slave
stop slave;
SET GLOBAL slave_parallel_threads=0;
set global slave_parallel_mode=conservative;
start slave;
--disconnect con1
--source include/rpl_end.inc

{noformat}

Sachin Setiya (Inactive) made changes - 2020-04-28 12:14

Description

{noformat:title=10.5 87a7968c}
2020-04-14 10:14:49 0 [Note] /ten1/builds/10.5-87a7968c-deb/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
2020-04-14 10:14:49 0 [Note] Event Scheduler: Purging the queue. 14 events
safe_mutex: Trying to lock uninitialized mutex at /home/elenst/src/10.5/sql/rpl_parallel.cc, line 470
200414 10:14:49 [ERROR] mysqld got signal 6 ;

#3 <signal handler called>
#4 0x00007f73a1ad5207 in raise () from /lib64/libc.so.6
#5 0x00007f73a1ad68f8 in abort () from /lib64/libc.so.6
#6 0x0000560ad0f8b4cf in safe_mutex_lock (mp=0x560ad1f58d90 <global_rpl_thread_pool+16>, my_flags=0, file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", line=470) at /home/elenst/src/10.5/mysys/thr_mutex.c:244
#7 0x0000560ad05107d1 in inline_mysql_mutex_lock (that=0x560ad1f58d90 <global_rpl_thread_pool+16>, src_file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", src_line=470) at /home/elenst/src/10.5/include/mysql/psi/mysql_thread.h:763
#8 0x0000560ad051229d in pool_mark_busy (pool=0x560ad1f58d80 <global_rpl_thread_pool>, thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:470
#9 0x0000560ad05126f2 in rpl_pause_for_ftwrl (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:563
#10 0x0000560ad02eb534 in mysql_execute_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5374
#11 0x0000560ad02f3912 in mysql_parse (thd=0x7f7328000b18, rawbuf=0x7f7328012460 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", length=51, parser_state=0x7f7384acf520, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:7953
#12 0x0000560ad02df2c0 in dispatch_command (command=COM_QUERY, thd=0x7f7328000b18, packet=0x7f7328008809 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", packet_length=51, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:1840
#13 0x0000560ad02dd93c in do_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:1359
#14 0x0000560ad0483c6d in do_handle_one_connection (connect=0x560ad51db8f8, put_in_cache=true) at /home/elenst/src/10.5/sql/sql_connect.cc:1422
#15 0x0000560ad0483986 in handle_one_connection (arg=0x560ad51db8f8) at /home/elenst/src/10.5/sql/sql_connect.cc:1319
#16 0x0000560ad09c173e in pfs_spawn_thread (arg=0x560ad52f7448) at /home/elenst/src/10.5/storage/perfschema/pfs.cc:2201
#17 0x00007f73a310bdd5 in start_thread () from /lib64/libpthread.so.0
#18 0x00007f73a1b9cead in clone () from /lib64/libc.so.6
{noformat}

The stack trace above is from an original failure in concurrent tests.

The test case below will produce a failure with line numbers in rpl_parallel.cc shifted by 1, due to the suggested debug injection.
Theoretically it can fail without the injection, but chances are slim, while with it it fails for me every time.

{noformat:title=injection}
index 9344312fe62..e42e6b2ebb5 100644
--- a/sql/rpl_parallel.cc
+++ b/sql/rpl_parallel.cc
@@ -467,6 +467,7 @@ pool_mark_busy(rpl_parallel_thread_pool *pool, THD *thd)
     So we protect the infrequent operations of FLUSH TABLES WITH READ LOCK and
     pool size changes with this condition wait.
   */
+ DBUG_EXECUTE_IF("sleep_mark_busy",my_sleep(1000000););
   mysql_mutex_lock(&pool->LOCK_rpl_thread_pool);
   if (thd)
   {
{noformat}
{code:sql|title=Test case}
--connect (con1,localhost,root,,)
SET DEBUG_DBUG='+d,sleep_mark_busy';
--send
  FLUSH TABLES WITH READ LOCK;

--connection default
--source include/restart_mysqld.inc
{code}

Reproducible on 10.4, 10.5.
Could not reproduce and didn't observe on 10.3.
I have no information if the problem has any effect on non-debug builds.

This also fails (when we are on slave with pool>threads >0)

{noformat}
--source include/master-slave.inc

--connection master

--connection slave
stop slave;
SET GLOBAL slave_parallel_threads=10;
set global slave_parallel_mode=optimistic;
change master to master_use_gtid=slave_pos;
start slave;
--connect (con1,127.0.0.1,root,,test,$SLAVE_MYPORT)
SET DEBUG_DBUG='+d,sleep_mark_busy';
--send
  FLUSH TABLES WITH READ LOCK;

--connection slave
--source include/rpl_restart_server.inc

--connection slave
stop slave;
SET GLOBAL slave_parallel_threads=0;
set global slave_parallel_mode=conservative;
start slave;
--disconnect con1
--source include/rpl_end.inc

{noformat}

{noformat:title=10.5 87a7968c}
2020-04-14 10:14:49 0 [Note] /ten1/builds/10.5-87a7968c-deb/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
2020-04-14 10:14:49 0 [Note] Event Scheduler: Purging the queue. 14 events
safe_mutex: Trying to lock uninitialized mutex at /home/elenst/src/10.5/sql/rpl_parallel.cc, line 470
200414 10:14:49 [ERROR] mysqld got signal 6 ;

#3 <signal handler called>
#4 0x00007f73a1ad5207 in raise () from /lib64/libc.so.6
#5 0x00007f73a1ad68f8 in abort () from /lib64/libc.so.6
#6 0x0000560ad0f8b4cf in safe_mutex_lock (mp=0x560ad1f58d90 <global_rpl_thread_pool+16>, my_flags=0, file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", line=470) at /home/elenst/src/10.5/mysys/thr_mutex.c:244
#7 0x0000560ad05107d1 in inline_mysql_mutex_lock (that=0x560ad1f58d90 <global_rpl_thread_pool+16>, src_file=0x560ad11aaf40 "/home/elenst/src/10.5/sql/rpl_parallel.cc", src_line=470) at /home/elenst/src/10.5/include/mysql/psi/mysql_thread.h:763
#8 0x0000560ad051229d in pool_mark_busy (pool=0x560ad1f58d80 <global_rpl_thread_pool>, thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:470
#9 0x0000560ad05126f2 in rpl_pause_for_ftwrl (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/rpl_parallel.cc:563
#10 0x0000560ad02eb534 in mysql_execute_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5374
#11 0x0000560ad02f3912 in mysql_parse (thd=0x7f7328000b18, rawbuf=0x7f7328012460 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", length=51, parser_state=0x7f7384acf520, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:7953
#12 0x0000560ad02df2c0 in dispatch_command (command=COM_QUERY, thd=0x7f7328000b18, packet=0x7f7328008809 "FLUSH /* QNO 1411 CON_ID 9 */ TABLES WITH READ LOCK", packet_length=51, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:1840
#13 0x0000560ad02dd93c in do_command (thd=0x7f7328000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:1359
#14 0x0000560ad0483c6d in do_handle_one_connection (connect=0x560ad51db8f8, put_in_cache=true) at /home/elenst/src/10.5/sql/sql_connect.cc:1422
#15 0x0000560ad0483986 in handle_one_connection (arg=0x560ad51db8f8) at /home/elenst/src/10.5/sql/sql_connect.cc:1319
#16 0x0000560ad09c173e in pfs_spawn_thread (arg=0x560ad52f7448) at /home/elenst/src/10.5/storage/perfschema/pfs.cc:2201
#17 0x00007f73a310bdd5 in start_thread () from /lib64/libpthread.so.0
#18 0x00007f73a1b9cead in clone () from /lib64/libc.so.6
{noformat}

The stack trace above is from an original failure in concurrent tests.

The test case below will produce a failure with line numbers in rpl_parallel.cc shifted by 1, due to the suggested debug injection.
Theoretically it can fail without the injection, but chances are slim, while with it it fails for me every time.

{noformat:title=injection}
index 9344312fe62..e42e6b2ebb5 100644
--- a/sql/rpl_parallel.cc
+++ b/sql/rpl_parallel.cc
@@ -467,6 +467,7 @@ pool_mark_busy(rpl_parallel_thread_pool *pool, THD *thd)
     So we protect the infrequent operations of FLUSH TABLES WITH READ LOCK and
     pool size changes with this condition wait.
   */
+ DBUG_EXECUTE_IF("sleep_mark_busy",my_sleep(1000000););
   mysql_mutex_lock(&pool->LOCK_rpl_thread_pool);
   if (thd)
   {
{noformat}
{code:sql|title=Test case}
--connect (con1,localhost,root,,)
SET DEBUG_DBUG='+d,sleep_mark_busy';
--send
  FLUSH TABLES WITH READ LOCK;

--connection default
--source include/restart_mysqld.inc
{code}

Reproducible on 10.4, 10.5.
Could not reproduce and didn't observe on 10.3.
I have no information if the problem has any effect on non-debug builds.

Sachin Setiya (Inactive) made changes - 2020-04-28 20:13

Status

Open [ 1 ]

In Progress [ 3 ]

Sachin Setiya (Inactive) made changes - 2020-04-28 20:13

Assignee	Sachin Setiya [ sachin.setiya.007 ]	Andrei Elkin [ elkin ]
Status	In Progress [ 3 ]	In Review [ 10002 ]

Andrei Elkin made changes - 2020-06-15 16:44

Assignee	Andrei Elkin [ elkin ]	Sachin Setiya [ sachin.setiya.007 ]
Status	In Review [ 10002 ]	Stalled [ 10000 ]

Sachin Setiya (Inactive) made changes - 2020-06-16 21:18

Fix Version/s		10.5.4 [ 24264 ]
Fix Version/s		10.4.14 [ 24305 ]
Fix Version/s	10.4 [ 22408 ]
Fix Version/s	10.5 [ 23123 ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2021-12-06 21:51

Workflow

MariaDB v3 [ 107766 ]

MariaDB v4 [ 157670 ]

People

Assignee:: Sachin Setiya (Inactive)

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2020-04-26 12:41

Updated:: 2021-05-14 10:50

Resolved:: 2020-06-16 21:18

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration