[MDEV-19745] BACKUP STAGE BLOCK_DDL hangs on flush sequence table Created: 2019-06-13  Updated: 2020-06-15  Resolved: 2020-06-15

Status: Closed
Project: MariaDB Server
Component/s: Sequences
Affects Version/s: 10.5
Fix Version/s: 10.5.4

Type: Bug Priority: Critical
Reporter: Vladislav Lesin Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: affects-tests

Attachments: HTML File mdev19745_threads1     HTML File mdev19745_threads2    
Issue Links:
Relates

 Description   

BACKUP STAGE BLOCK_DDL hangs with the following test case:

--source include/have_innodb.inc
 
--connect(con1,localhost,root,,)
 
--connection default
 
 
 
--let $i=10000
 
CREATE SEQUENCE s START WITH 100 INCREMENT BY 10;
 
ALTER TABLE s ENGINE=InnoDB;
 
 
 
 
 
while($i) {
 
SELECT NEXTVAL(s);
 
SELECT NEXTVAL(s);
 
 
 
--connection con1
 
BACKUP STAGE START;
 
BACKUP STAGE FLUSH;
 
--connection default
 
--send ALTER SEQUENCE IF EXISTS s INCREMENT = 9 MAXVALUE 4735816483156787200 MINVALUE 90;
 
--connection con1
 
BACKUP STAGE BLOCK_DDL;
 
BACKUP STAGE BLOCK_COMMIT;
 
BACKUP STAGE END;
 
--connection default
 
--reap
 
--dec $i
 
}

The backtrace:

Thread 28 (Thread 0x7fa86ddad700 (LWP 1521)):
 
#0  0x00007fa8780d6f85 in futex_abstimed_wait_cancelable (private=<optimized out>, abstime=0x7fa86ddaaec0, expected=0, futex_word=0x7fa814000f6c) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
 
#1  __pthread_cond_wait_common (abstime=0x7fa86ddaaec0, mutex=0x7fa814000eb8, cond=0x7fa814000f40) at pthread_cond_wait.c:539
 
#2  __pthread_cond_timedwait (cond=0x7fa814000f40, mutex=0x7fa814000eb8, abstime=0x7fa86ddaaec0) at pthread_cond_wait.c:667
 
#3  0x000055f66a1dbb86 in safe_cond_timedwait (cond=0x7fa814000f40, mp=0x7fa814000e90, abstime=0x7fa86ddaaec0, 
    file=0x55f66a2e9f00 "./include/mysql/psi/mysql_thread.h", line=1215) at ./mysys/thr_mutex.c:546
 
#4  0x000055f6698ad6e6 in inline_mysql_cond_timedwait (that=0x7fa814000f40, mutex=0x7fa814000e90, abstime=0x7fa86ddaaec0)
 
    at ./include/mysql/psi/mysql_thread.h:1215
 
#5  0x000055f6698ae919 in MDL_wait::timed_wait (this=0x7fa814000e90, owner=0x7fa814000e40, abs_timeout=0x7fa86ddaaec0, set_status_on_timeout=false, 
    wait_state_name=0x55f66acfe1b0 <MDL_key::m_namespace_to_wait_state_name+48>) at ./sql/mdl.cc:1147
 
#6  0x000055f6698b057a in MDL_context::acquire_lock (this=0x7fa814000e90, mdl_request=0x7fa86ddab010, lock_wait_timeout=86400) at ./sql/mdl.cc:2325
 
#7  0x000055f6698b0a15 in MDL_context::acquire_locks (this=0x7fa814000e90, mdl_requests=0x7fa86ddaafe0, lock_wait_timeout=86400) at ./sql/mdl.cc:2447
 
#8  0x000055f66995a603 in SEQUENCE::read_initial_values (this=0x7fa820166ef8, table=0x7fa8140511c0) at ./sql/sql_sequence.cc:460
 
#9  0x000055f66a1a5900 in ha_sequence::open (this=0x7fa8140532b8, name=0x7fa8200d6210 "./test/s", mode=2, flags=8194) at ./sql/ha_sequence.cc:114
 
#10 0x000055f669a66d8a in handler::ha_open (this=0x7fa8140532b8, table_arg=0x7fa8140511c0, name=0x7fa8200d6210 "./test/s", mode=2, test_if_locked=8194, mem_root=0x0, partitions_to_open=0x0)
 
    at ./sql/handler.cc:2688
 
#11 0x000055f66984da1d in open_table_from_share (thd=0x7fa814000d70, share=0x7fa8200d5c88, alias=0x55f66abb16c0 <empty_clex_str>, db_stat=1, prgflag=0, ha_open_flags=8194, outparam=0x7fa8140511c0, 
    is_create_table=false, partitions_to_open=0x0) at ./sql/table.cc:3878
 
#12 0x000055f6696925f3 in flush_tables (thd=0x7fa814000d70, flag=FLUSH_NON_TRANS_TABLES) at ./sql/sql_base.cc:574
 
#13 0x000055f6699a18af in backup_block_ddl (thd=0x7fa814000d70) at ./sql/backup.cc:255
 
#14 0x000055f6699a1462 in run_backup_stage (thd=0x7fa814000d70, stage=BACKUP_WAIT_FOR_FLUSH) at ./sql/backup.cc:113
 
#15 0x000055f669734e5a in mysql_execute_command (thd=0x7fa814000d70) at ./sql/sql_parse.cc:5298
 
#16 0x000055f66973ec79 in mysql_parse (thd=0x7fa814000d70, rawbuf=0x7fa814012098 "BACKUP STAGE BLOCK_DDL", length=22, parser_state=0x7fa86ddac180, is_com_multi=false, is_next_command=false)
 
    at ./sql/sql_parse.cc:8163
 
#17 0x000055f66972a4dd in dispatch_command (command=COM_QUERY, thd=0x7fa814000d70, packet=0x7fa8140087b1 "BACKUP STAGE BLOCK_DDL", packet_length=22, is_com_multi=false, is_next_command=false)
 
    at ./sql/sql_parse.cc:1828
 
#18 0x000055f669728d11 in do_command (thd=0x7fa814000d70) at ./sql/sql_parse.cc:1361
 
#19 0x000055f6698a236d in do_handle_one_connection (connect=0x55f66cd51b90, put_in_cache=true) at ./sql/sql_connect.cc:1413
 
#20 0x000055f6698a20b2 in handle_one_connection (arg=0x55f66cd51b90) at ./sql/sql_connect.cc:1309
 
#21 0x00007fa8780d06db in start_thread (arg=0x7fa86ddad700) at pthread_create.c:463
 
#22 0x00007fa8772b688f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
 
 
Thread 27 (Thread 0x7fa86ddf8700 (LWP 1518)):
 
#0  0x00007fa8780d5938 in futex_abstimed_wait (private=<optimized out>, abstime=0x0, expected=3, futex_word=0x7fa820166f64) at ../sysdeps/unix/sysv/linux/futex-internal.h:172
 
#1  __pthread_rwlock_wrlock_full (abstime=0x0, rwlock=0x7fa820166f58) at pthread_rwlock_common.c:706
 
#2  __GI___pthread_rwlock_wrlock (rwlock=0x7fa820166f58) at pthread_rwlock_wrlock.c:27
 
#3  0x000055f6699591a7 in inline_mysql_rwlock_wrlock (that=0x7fa820166f58) at ./include/mysql/psi/mysql_thread.h:964
 
#4  0x000055f66995a367 in SEQUENCE::write_lock (this=0x7fa820166ef8, table=0x7fa8200bb280) at ./sql/sql_sequence.cc:401
 
#5  0x000055f66995a4d2 in SEQUENCE::read_initial_values (this=0x7fa820166ef8, table=0x7fa8200bb280) at ./sql/sql_sequence.cc:434
 
#6  0x000055f66a1a5900 in ha_sequence::open (this=0x7fa820109f28, name=0x7fa8200d6210 "./test/s", mode=2, flags=18) at ./sql/ha_sequence.cc:114
 
#7  0x000055f669a66d8a in handler::ha_open (this=0x7fa820109f28, table_arg=0x7fa8200bb280, name=0x7fa8200d6210 "./test/s", mode=2, test_if_locked=18, mem_root=0x0, partitions_to_open=0x0)
 
    at ./sql/handler.cc:2688
 
#8  0x000055f66984da1d in open_table_from_share (thd=0x7fa820000d70, share=0x7fa8200d5c88, alias=0x7fa820013438, db_stat=33, prgflag=8, ha_open_flags=18, outparam=0x7fa8200bb280, is_create_table=false, 
    partitions_to_open=0x0) at ./sql/table.cc:3878
 
#9  0x000055f669695485 in open_table (thd=0x7fa820000d70, table_list=0x7fa8200133f0, ot_ctx=0x7fa86ddf6150) at ./sql/sql_base.cc:2043
 
#10 0x000055f66969891f in open_and_process_table (thd=0x7fa820000d70, tables=0x7fa8200133f0, counter=0x7fa86ddf6234, flags=0, prelocking_strategy=0x7fa86ddf62b8, has_prelocking_list=false, 
    ot_ctx=0x7fa86ddf6150) at ./sql/sql_base.cc:3802
 
#11 0x000055f669699c99 in open_tables (thd=0x7fa820000d70, options=..., start=0x7fa86ddf6218, counter=0x7fa86ddf6234, sroutine_to_open_list=0x7fa820004ad0, flags=0, prelocking_strategy=0x7fa86ddf62b8)
 
    at ./sql/sql_base.cc:4301
 
#12 0x000055f669691229 in open_tables (thd=0x7fa820000d70, options=..., tables=0x7fa86ddf6218, counter=0x7fa86ddf6234, flags=0, prelocking_strategy=0x7fa86ddf62b8)
 
    at ./sql/sql_base.h:260
 
#13 0x000055f66969ba79 in open_and_lock_tables (thd=0x7fa820000d70, options=..., tables=0x7fa8200133f0, derived=false, flags=0, prelocking_strategy=0x7fa86ddf62b8)
 
    at ./sql/sql_base.cc:5185
 
---Type <return> to continue, or q <return> to quit---
 
#14 0x000055f669658ca4 in open_and_lock_tables (thd=0x7fa820000d70, tables=0x7fa8200133f0, derived=false, flags=0) at ./sql/sql_base.h:513
 
#15 0x000055f66995b7eb in Sql_cmd_alter_sequence::execute (this=0x7fa820013ac8, thd=0x7fa820000d70) at ./sql/sql_sequence.cc:894
 
#16 0x000055f669739a6c in mysql_execute_command (thd=0x7fa820000d70) at ./sql/sql_parse.cc:6354
 
#17 0x000055f66973ec79 in mysql_parse (thd=0x7fa820000d70, rawbuf=0x7fa820013248 "ALTER SEQUENCE IF EXISTS s INCREMENT = 9 MAXVALUE 4735816483156787200 MINVALUE 90", length=81, parser_state=0x7fa86ddf7180, 
    is_com_multi=false, is_next_command=false) at ./sql/sql_parse.cc:8163
 
#18 0x000055f66972a4dd in dispatch_command (command=COM_QUERY, thd=0x7fa820000d70, packet=0x7fa82010e6c1 "ALTER SEQUENCE IF EXISTS s INCREMENT = 9 MAXVALUE 4735816483156787200 MINVALUE 90;", packet_length=82, 
    is_com_multi=false, is_next_command=false) at ./sql/sql_parse.cc:1828
 
#19 0x000055f669728d11 in do_command (thd=0x7fa820000d70) at ./sql/sql_parse.cc:1361
 
#20 0x000055f6698a236d in do_handle_one_connection (connect=0x55f66cd5f710, put_in_cache=true) at ./sql/sql_connect.cc:1413
 
#21 0x000055f6698a20b2 in handle_one_connection (arg=0x55f66cd29910) at ./sql/sql_connect.cc:1309
 
#22 0x00007fa8780d06db in start_thread (arg=0x7fa86ddf8700) at pthread_create.c:463
 
#23 0x00007fa8772b688f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95



 Comments   
Comment by Michael Widenius [ 2019-06-24 ]

I have run MDEV-19745 BACKUP STAGE BLOCK_DDL hangs on flush sequence table 4 times and no problems with 10.4 and 10.5

The lock requested is MDL_SHARED_READ, MDL_EXPLICIT at sql_sequence.cc:460
I can't see anything in Sql_cmd_alter_sequence::execute that could conflict with that lock.
If you get this problem again, please provide a full back trace for all threads so that we can see where the ALTER SEQUENCE thread is stuck.

Comment by Elena Stepanova [ 2019-07-05 ]

It is reproducible readily for me with Vlad's test case.
Two consequent full all thread stack traces from 10.5 a6946c55 are attached (from the same process, taken with a half of a minute interval or so): mdev19745_threads1 mdev19745_threads2

Comment by Michael Widenius [ 2020-06-08 ]

Problem was that FLUSH TABLES where trying to read latest sequence state which conflicted with a running ALTER SEQUENCE. Removed the reading of the state, when opening a table for FLUSH, as it's not needed in this case.

Comment by Michael Widenius [ 2020-06-15 ]

Problem was that FLUSH TABLES where trying to read latest sequence state which conflicted with a running ALTER SEQUENCE. Removed the reading of the state, when opening a table for FLUSH,
as it's not needed in this case.

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