[MDEV-13797] InnoDB may hang if shutdown is initiated soon after startup, while rolling back recovered incomplete transactions Created: 2017-09-13  Updated: 2020-08-25  Resolved: 2017-12-13

Status: Closed
Project: MariaDB Server
Component/s: Backup, Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.1.23, 10.2.5, 10.0.31
Fix Version/s: 10.0.34, 10.1.30, 10.2.12, 10.3.3

Type: Bug Priority: Major
Reporter: Geoff Montee (Inactive) Assignee: Marko Mäkelä
Resolution: Fixed Votes: 1
Labels: backup, hang, innodb, recovery, shutdown

Issue Links:
Duplicate
is duplicated by MDEV-13808 (draft) possible hang on shutdown Closed
Problem/Incident
is caused by MDEV-12091 Shutdown fails to wait for rollback o... Closed
Relates
relates to MDEV-12323 Rollback progress log messages during... Closed
relates to MDEV-13807 mariabackup --apply-log-only does gen... Closed
Sprint: 10.2.11

 Description   

A user running mariabackup from 10.1.25 is seeing the tool hang while preparing an incremental backup. It seems to hang while attempting to rollback some transactions. The log contains information such as the following:

InnoDB: Starting in background the rollback of recovered transactions
 
2017-09-05 10:39:24 7fe54ab38700  InnoDB: Rolling back trx with id 614757352, 0 rows to undo
 
InnoDB: Waiting for purge to start
 
InnoDB: Rollback of trx with id 614757352 completed
 
2017-09-05 10:39:24 7fe54ab38700  InnoDB: Rolling back trx with id 614757351, 0 rows to undo
 
InnoDB: Rollback of trx with id 614757351 completed
 
2017-09-05 10:39:24 7fe54ab38700  InnoDB: Rolling back trx with id 614757350, 4 rows to undo
 
InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.0 started; log sequence number 7128840461184
 
InnoDB: Rollback of trx with id 614757350 completed
 
2017-09-05 10:39:24 7fe54ab38700  InnoDB: Rolling back trx with id 614757349, 192 rows to undo
 
InnoDB: Dumping buffer pool(s) not yet started
 
InnoDB: Last MySQL binlog file position 0 359629094, file name /data/replication/binlogs/mysql-bin.005032
 
 
 
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
 
InnoDB: FTS optimize thread exiting.
 
InnoDB: Starting shutdown...
 
InnoDB: Rollback of trx with id 614757349 completed
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit
 
InnoDB: Waiting for rollback of recovered transactions to exit

According to gdb, it looks like the rollback thread might be waiting on a mutex:

Thread 4 (Thread 0x7fe54ab38700 (LWP 1168)):
 
#0 mutex_enter_func (line=770, file_name=0x55c9275a9c10 "/opt/install/mariadb-10.1.25/storage/xtradb/trx/trx0roll.cc", mutex=0x7fe55c3d0068) at /opt/install/mariadb-10.1.25/storage/xtradb/include/sync0sync.ic:268
 
#1 pfs_mutex_enter_func (line=770, file_name=0x55c9275a9c10 "/opt/install/mariadb-10.1.25/storage/xtradb/trx/trx0roll.cc", mutex=0x7fe55c3d0068) at /opt/install/mariadb-10.1.25/storage/xtradb/include/sync0sync.ic:381
 
#2 trx_rollback_or_clean_recovered (all=<optimized out>, all@entry=1) at /opt/install/mariadb-10.1.25/storage/xtradb/trx/trx0roll.cc:770
 
#3 0x000055c927303759 in trx_rollback_or_clean_all_recovered (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/trx/trx0roll.cc:828
 
#4 0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#5 0x00007fe55f02534d in clone () from /lib64/libc.so.6

Here is the full backtrace for all threads:

 
 
Thread 14 (Thread 0x7fe55abfe700 (LWP 1156)):
 
#0  0x00007fe560c99945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x000055c927284feb in os_cond_wait (fast_mutex=0x7fe55b4993c0, cond=0x7fe55b4993f8) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:196
 
#2  os_event_wait_low (event=0x7fe55b4993c0, reset_sig_count=1, reset_sig_count@entry=0) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:477
 
#3  0x000055c9272839d4 in os_aio_simulated_handle (global_segment=global_segment@entry=0, message1=message1@entry=0x7fe55abfdd40, message2=message2@entry=0x7fe55abfdd48, type=type@entry=0x7fe55abfdd50, 
    space_id=space_id@entry=0x7fe55abfdd58) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0file.cc:5974
 
#4  0x000055c9271dba6a in fil_aio_wait (segment=segment@entry=0) at /opt/install/mariadb-10.1.25/storage/xtradb/fil/fil0fil.cc:6512
 
#5  0x000055c9272ec658 in io_handler_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/srv/srv0start.cc:586
 
#6  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#7  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 13 (Thread 0x7fe55b3ff700 (LWP 1157)):
 
#0  0x00007fe560c99945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x000055c927284feb in os_cond_wait (fast_mutex=0x7fe55b499350, cond=0x7fe55b499388) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:196
 
#2  os_event_wait_low (event=0x7fe55b499350, reset_sig_count=4, reset_sig_count@entry=0) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:477
 
#3  0x000055c9272839d4 in os_aio_simulated_handle (global_segment=global_segment@entry=1, message1=message1@entry=0x7fe55b3fed40, message2=message2@entry=0x7fe55b3fed48, type=type@entry=0x7fe55b3fed50, 
    space_id=space_id@entry=0x7fe55b3fed58) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0file.cc:5974
 
#4  0x000055c9271dba6a in fil_aio_wait (segment=segment@entry=1) at /opt/install/mariadb-10.1.25/storage/xtradb/fil/fil0fil.cc:6512
 
#5  0x000055c9272ec658 in io_handler_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/srv/srv0start.cc:586
 
#6  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#7  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 12 (Thread 0x7fe55a3fd700 (LWP 1158)):
 
#0  0x00007fe560c99945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x000055c927284feb in os_cond_wait (fast_mutex=0x7fe55b4992e0, cond=0x7fe55b499318) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:196
 
#2  os_event_wait_low (event=0x7fe55b4992e0, reset_sig_count=45, reset_sig_count@entry=0) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:477
 
#3  0x000055c9272839d4 in os_aio_simulated_handle (global_segment=global_segment@entry=2, message1=message1@entry=0x7fe55a3fcd40, message2=message2@entry=0x7fe55a3fcd48, type=type@entry=0x7fe55a3fcd50, 
    space_id=space_id@entry=0x7fe55a3fcd58) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0file.cc:5974
 
#4  0x000055c9271dba6a in fil_aio_wait (segment=segment@entry=2) at /opt/install/mariadb-10.1.25/storage/xtradb/fil/fil0fil.cc:6512
 
#5  0x000055c9272ec658 in io_handler_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/srv/srv0start.cc:586
 
#6  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#7  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 11 (Thread 0x7fe559bfc700 (LWP 1159)):
 
#0  0x00007fe560c99945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x000055c927284feb in os_cond_wait (fast_mutex=0x7fe55b499270, cond=0x7fe55b4992a8) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:196
 
#2  os_event_wait_low (event=0x7fe55b499270, reset_sig_count=72, reset_sig_count@entry=0) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:477
 
#3  0x000055c9272839d4 in os_aio_simulated_handle (global_segment=global_segment@entry=3, message1=message1@entry=0x7fe559bfbd40, message2=message2@entry=0x7fe559bfbd48, type=type@entry=0x7fe559bfbd50, 
    space_id=space_id@entry=0x7fe559bfbd58) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0file.cc:5974
 
#4  0x000055c9271dba6a in fil_aio_wait (segment=segment@entry=3) at /opt/install/mariadb-10.1.25/storage/xtradb/fil/fil0fil.cc:6512
 
#5  0x000055c9272ec658 in io_handler_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/srv/srv0start.cc:586
 
#6  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#7  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 10 (Thread 0x7fe54e33f700 (LWP 1160)):
 
#0  0x00007fe560c99945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x000055c927284feb in os_cond_wait (fast_mutex=0x7fe55b499200, cond=0x7fe55b499238) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:196
 
#2  os_event_wait_low (event=0x7fe55b499200, reset_sig_count=19, reset_sig_count@entry=0) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:477
 
#3  0x000055c9272839d4 in os_aio_simulated_handle (global_segment=global_segment@entry=4, message1=message1@entry=0x7fe54e33ed40, message2=message2@entry=0x7fe54e33ed48, type=type@entry=0x7fe54e33ed50, 
    space_id=space_id@entry=0x7fe54e33ed58) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0file.cc:5974
 
#4  0x000055c9271dba6a in fil_aio_wait (segment=segment@entry=4) at /opt/install/mariadb-10.1.25/storage/xtradb/fil/fil0fil.cc:6512
 
#5  0x000055c9272ec658 in io_handler_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/srv/srv0start.cc:586
 
#6  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#7  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 9 (Thread 0x7fe54db3e700 (LWP 1161)):
 
#0  0x00007fe560c99945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x000055c927284feb in os_cond_wait (fast_mutex=0x7fe55b499190, cond=0x7fe55b4991c8) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:196
 
#2  os_event_wait_low (event=0x7fe55b499190, reset_sig_count=117, reset_sig_count@entry=0) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:477
 
#3  0x000055c9272839d4 in os_aio_simulated_handle (global_segment=global_segment@entry=5, message1=message1@entry=0x7fe54db3dd40, message2=message2@entry=0x7fe54db3dd48, type=type@entry=0x7fe54db3dd50, 
    space_id=space_id@entry=0x7fe54db3dd58) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0file.cc:5974
 
#4  0x000055c9271dba6a in fil_aio_wait (segment=segment@entry=5) at /opt/install/mariadb-10.1.25/storage/xtradb/fil/fil0fil.cc:6512
 
#5  0x000055c9272ec658 in io_handler_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/srv/srv0start.cc:586
 
#6  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#7  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 8 (Thread 0x7fe54d33d700 (LWP 1162)):
 
#0  0x00007fe560c99945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x000055c927284feb in os_cond_wait (fast_mutex=0x7fe55b499120, cond=0x7fe55b499158) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:196
 
#2  os_event_wait_low (event=0x7fe55b499120, reset_sig_count=119, reset_sig_count@entry=0) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:477
 
#3  0x000055c9272839d4 in os_aio_simulated_handle (global_segment=global_segment@entry=6, message1=message1@entry=0x7fe54d33cd40, message2=message2@entry=0x7fe54d33cd48, type=type@entry=0x7fe54d33cd50, 
    space_id=space_id@entry=0x7fe54d33cd58) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0file.cc:5974
 
#4  0x000055c9271dba6a in fil_aio_wait (segment=segment@entry=6) at /opt/install/mariadb-10.1.25/storage/xtradb/fil/fil0fil.cc:6512
 
#5  0x000055c9272ec658 in io_handler_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/srv/srv0start.cc:586
 
#6  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#7  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 7 (Thread 0x7fe54cb3c700 (LWP 1163)):
 
#0  0x00007fe560c99945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x000055c927284feb in os_cond_wait (fast_mutex=0x7fe55b4990b0, cond=0x7fe55b4990e8) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:196
 
#2  os_event_wait_low (event=0x7fe55b4990b0, reset_sig_count=114, reset_sig_count@entry=0) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:477
 
#3  0x000055c9272839d4 in os_aio_simulated_handle (global_segment=global_segment@entry=7, message1=message1@entry=0x7fe54cb3bd40, message2=message2@entry=0x7fe54cb3bd48, type=type@entry=0x7fe54cb3bd50, 
    space_id=space_id@entry=0x7fe54cb3bd58) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0file.cc:5974
 
#4  0x000055c9271dba6a in fil_aio_wait (segment=segment@entry=7) at /opt/install/mariadb-10.1.25/storage/xtradb/fil/fil0fil.cc:6512
 
#5  0x000055c9272ec658 in io_handler_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/srv/srv0start.cc:586
 
#6  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#7  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 6 (Thread 0x7fe54c33b700 (LWP 1164)):
 
#0  0x00007fe560c99945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x000055c927284feb in os_cond_wait (fast_mutex=0x7fe55b499040, cond=0x7fe55b499078) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:196
 
#2  os_event_wait_low (event=0x7fe55b499040, reset_sig_count=128, reset_sig_count@entry=0) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:477
 
#3  0x000055c9272839d4 in os_aio_simulated_handle (global_segment=global_segment@entry=8, message1=message1@entry=0x7fe54c33ad40, message2=message2@entry=0x7fe54c33ad48, type=type@entry=0x7fe54c33ad50, 
    space_id=space_id@entry=0x7fe54c33ad58) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0file.cc:5974
 
#4  0x000055c9271dba6a in fil_aio_wait (segment=segment@entry=8) at /opt/install/mariadb-10.1.25/storage/xtradb/fil/fil0fil.cc:6512
 
#5  0x000055c9272ec658 in io_handler_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/srv/srv0start.cc:586
 
#6  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#7  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 5 (Thread 0x7fe54bb3a700 (LWP 1165)):
 
#0  0x00007fe560c99945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x000055c927284feb in os_cond_wait (fast_mutex=0x7fe55b498fd0, cond=0x7fe55b499008) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:196
 
#2  os_event_wait_low (event=0x7fe55b498fd0, reset_sig_count=109, reset_sig_count@entry=0) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0sync.cc:477
 
#3  0x000055c9272839d4 in os_aio_simulated_handle (global_segment=global_segment@entry=9, message1=message1@entry=0x7fe54bb39d40, message2=message2@entry=0x7fe54bb39d48, type=type@entry=0x7fe54bb39d50, 
    space_id=space_id@entry=0x7fe54bb39d58) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0file.cc:5974
 
#4  0x000055c9271dba6a in fil_aio_wait (segment=segment@entry=9) at /opt/install/mariadb-10.1.25/storage/xtradb/fil/fil0fil.cc:6512
 
#5  0x000055c9272ec658 in io_handler_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/srv/srv0start.cc:586
 
#6  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#7  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 4 (Thread 0x7fe54ab38700 (LWP 1168)):
 
#0  mutex_enter_func (line=770, file_name=0x55c9275a9c10 "/opt/install/mariadb-10.1.25/storage/xtradb/trx/trx0roll.cc", mutex=0x7fe55c3d0068) at /opt/install/mariadb-10.1.25/storage/xtradb/include/sync0sync.ic:268
 
#1  pfs_mutex_enter_func (line=770, file_name=0x55c9275a9c10 "/opt/install/mariadb-10.1.25/storage/xtradb/trx/trx0roll.cc", mutex=0x7fe55c3d0068) at /opt/install/mariadb-10.1.25/storage/xtradb/include/sync0sync.ic:381
 
#2  trx_rollback_or_clean_recovered (all=<optimized out>, all@entry=1) at /opt/install/mariadb-10.1.25/storage/xtradb/trx/trx0roll.cc:770
 
#3  0x000055c927303759 in trx_rollback_or_clean_all_recovered (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/trx/trx0roll.cc:828
 
#4  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#5  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 3 (Thread 0x7fe547331700 (LWP 1175)):
 
#0  0x00007fe55f01c7a3 in select () from /lib64/libc.so.6
 
#1  0x000055c92728587b in os_thread_sleep (tm=tm@entry=100000) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0thread.cc:307
 
#2  0x000055c9271a3fa2 in buf_flush_page_cleaner_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/buf/buf0flu.cc:2871
 
#3  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#4  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 2 (Thread 0x7fe546b30700 (LWP 1176)):
 
#0  0x00007fe55f01c7a3 in select () from /lib64/libc.so.6
 
#1  0x000055c92728587b in os_thread_sleep (tm=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0thread.cc:307
 
#2  0x000055c92719dfde in page_cleaner_sleep_if_needed (next_loop_time=next_loop_time@entry=1504629392984) at /opt/install/mariadb-10.1.25/storage/xtradb/buf/buf0flu.cc:2668
 
#3  0x000055c9271a48ff in page_cleaner_sleep_if_needed (next_loop_time=1504629392984) at /opt/install/mariadb-10.1.25/storage/xtradb/buf/buf0flu.cc:2956
 
#4  buf_flush_lru_manager_thread (arg=<optimized out>) at /opt/install/mariadb-10.1.25/storage/xtradb/buf/buf0flu.cc:2958
 
#5  0x00007fe560c95e25 in start_thread () from /lib64/libpthread.so.0
 
#6  0x00007fe55f02534d in clone () from /lib64/libc.so.6
 
 
 
Thread 1 (Thread 0x7fe56107f8c0 (LWP 1148)):
 
#0  0x00007fe55f01c7a3 in select () from /lib64/libc.so.6
 
#1  0x000055c92728587b in os_thread_sleep (tm=tm@entry=100000) at /opt/install/mariadb-10.1.25/storage/xtradb/os/os0thread.cc:307
 
#2  0x000055c927269aef in logs_empty_and_mark_files_at_shutdown () at /opt/install/mariadb-10.1.25/storage/xtradb/log/log0log.cc:3555
 
#3  0x000055c9272f0ee4 in innodb_shutdown () at /opt/install/mariadb-10.1.25/storage/xtradb/srv/srv0start.cc:3208
 
#4  0x000055c926e2f575 in innodb_end () at /opt/install/mariadb-10.1.25/extra/mariabackup/xtrabackup.cc:1760
 
#5  0x000055c926e16a55 in xtrabackup_prepare_func (argv=<optimized out>, argc=<optimized out>) at /opt/install/mariadb-10.1.25/extra/mariabackup/xtrabackup.cc:6021
 
#6  main (argc=<optimized out>, argv=<optimized out>) at /opt/install/mariadb-10.1.25/extra/mariabackup/xtrabackup.cc:6658

The utility was run in the following way:

Full backup:

mariabackup --defaults-file=/etc/my.cnf.d/server.cnf --user=root --backup --target-dir=/path/to/backup/full --safe-slave-backup --slave-info --open-files-limit=65535 --host=127.0.0.1 --port=3306

Incremental backup:

mariabackup --defaults-file=/etc/my.cnf.d/server.cnf --user=root --backup --incremental-force-scan --safe-slave-backup --slave-info --open-files-limit=65535 --incremental-basedir=/path/to/backup/full --target-dir=/path/to/backup/incr --host=127.0.0.1 --port=3306

Full prepare:

mariabackup --defaults-file=/etc/my.cnf.d/server.cnf --prepare --apply-log-only --target-dir=/path/to/backup/full

Incremental prepare (which hangs):

mariabackup --defaults-file=/etc/my.cnf.d/server.cnf --prepare --apply-log-only --target-dir=/path/to/backup/full --incremental-dir=/path/to/backup/incr

 Comments   
Comment by Marko Mäkelä [ 2017-09-14 ]

I see the following problems:

  1. --apply-log-only is not preventing the rollback from happening (MDEV-13807)
  2. the rollback progress reporting is inadequate (MDEV-12323)
  3. the rollback of one transaction is never finished (never started?)

It looks like the last problem was introduced by MDEV-12091. When the rollback thread detects that normal shutdown has been requested, trx_rollback_or_clean_recovered() will stop rolling back further transactions:

			if (srv_shutdown_state != SRV_SHUTDOWN_NONE
 
			    && srv_fast_shutdown != 0) {
 
				all = FALSE;
 
				break;
 
			}

But, logs_empty_and_mark_files_at_shutdown() will keep waiting until the number of transactions reaches 0:

	if (ulint total_trx = srv_was_started && !srv_read_only_mode
 
	    && srv_force_recovery < SRV_FORCE_NO_TRX_UNDO
 
	    ? trx_sys_any_active_transactions() : 0) {
 
		if (srv_print_verbose_log && count > 600) {
 
			ib_logf(IB_LOG_LEVEL_INFO,
 
				"Waiting for %lu active transactions to finish",
 
				(ulong) total_trx);
 
 
 
			count = 0;
 
		}
 
 
 
		goto loop;
 
	}

This will never happen.
This should be repeatable with the MariaDB server as well:

  1. Start a number of transactions that modify data.
  2. In one connection, SET GLOBAL innodb_flush_log_at_trx_commit=1; and commit a small change to an InnoDB table. This ensures that the changes from the above incomplete transactions are persisted in the redo log.
  3. Kill the server.
  4. Restart and quickly shut down the server. It should hang on shutdown.
Comment by Andrii Nikitin (Inactive) [ 2017-09-15 ]

GeoffMontee According to provided analysis - hanging itself is not that dangerous - because all redo logs are already properly applied. So workaround should be just killing mariabackup process after seeing message "InnoDB: ... started" .

But much bigger issue is presence of messages "InnoDB: Rollback of trx with id .... completed" when --apply-log-only flag present.
That shouldn't happen and means that incremental backup may lose data from those transactions which where started before (intermediate) backups start and committed after completion of those backups .
I've opened MDEV-13807 for that problem , which also means that incremental backup cannot be safely used in 10.1

marko I've confirmed #1 per your instructions, working on #3

Comment by Andrii Nikitin (Inactive) [ 2017-09-15 ]

I've confirmed #3 manually with steps below, working on mtr test:

# started with innodb_flush_log_at_trx_commit=1 innodb_buffer_pool_size=4G innodb_log_file_size=256M innodb_log_buffer_size=256M (not sure which are relevant yet)
 
for i in {1..20} ; do mysql -e "create table t$i select 1; start transaction; insert into t$i select seq from seq_1_to_1000000; do sleep(1000)" test 2>/dev/null & done
 
mysql -e 'drop table if exists t' test
 
mysql -e "create table t select 1" test
 
sleep 10
 
mysql -e 'insert into t select 1' test
 
 
 
kill -9 $(cat $eid*/dt/p.id)
 
$eid*/startup.sh &
 
 
 
# make sure we shutdown at first possible moment
 
while : ; do
 
if mysqladmin shutdown ; then
 
  break
 
else
 
  continue
 
fi
 
done

Error Log:

2017-09-15 11:52:11 139895907113920 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 1616717
 
2017-09-15 11:52:11 139895907113920 [Note] Plugin 'FEEDBACK' is disabled.
 
2017-09-15 11:52:11 139890167609088 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2017-09-15 11:52:11 139895907113920 [Note] Server socket created on IP: '::'.
 
2017-09-15 11:52:11 139895907113920 [Note] /home/a/mariadb-environs/m2-10.1/build/sql//mysqld: ready for connections.
 
Version: '10.1.27-MariaDB-debug'  socket: '/home/a/mariadb-environs/m2-10.1/dt/my.sock'  port: 3308  Source distribution
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: The InnoDB memory heap is disabled
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: Using Linux native AIO
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: Using SSE crc32 instructions
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: Initializing buffer pool, size = 4.0G
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: Completed initialization of buffer pool
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1616727
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
 
InnoDB: 20 transaction(s) which must be rolled back or cleaned up
 
InnoDB: in total 25281 row operations to undo
 
InnoDB: Trx id counter is 2816
 
2017-09-15 11:52:30 140200330218432 [Note] InnoDB: Starting final batch to recover 153 pages from redo log
 
2017-09-15 11:52:32 140194686691072 [Note] InnoDB: Starting in background the rollback of recovered transactions
 
2017-09-15 11:52:32 7f819e7fe700  InnoDB: Rolling back trx with id 2436, 1308 rows to undo
 
 
 
InnoDB: Progress in percents: 12017-09-15 11:52:32 140200330218432 [Note] InnoDB: 128 rollback segment(s) are active.
 
2017-09-15 11:52:32 140200330218432 [Note] InnoDB: Waiting for purge to start
 
 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 362017-09-15 11:52:32 140200330218432 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 3873533
 
 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-09-15 11:52:33 140194686691072 [Note] InnoDB: Rollback of trx with id 2436 completed
 
2017-09-15 11:52:33 7f819e7fe700  InnoDB: Rolling back trx with id 2435, 1255 rows to undo
 
 
 
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-09-15 11:52:34 140194686691072 [Note] InnoDB: Rollback of trx with id 2435 completed
 
2017-09-15 11:52:34 7f819e7fe700  InnoDB: Rolling back trx with id 2434, 1169 rows to undo
 
 
 
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-09-15 11:52:34 140194686691072 [Note] InnoDB: Rollback of trx with id 2434 completed
 
2017-09-15 11:52:34 7f819e7fe700  InnoDB: Rolling back trx with id 2433, 1227 rows to undo
 
 
 
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-09-15 11:52:34 140194686691072 [Note] InnoDB: Rollback of trx with id 2433 completed
 
2017-09-15 11:52:34 7f819e7fe700  InnoDB: Rolling back trx with id 2432, 1231 rows to undo
 
 
 
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-09-15 11:52:35 140194686691072 [Note] InnoDB: Rollback of trx with id 2432 completed
 
2017-09-15 11:52:35 7f819e7fe700  InnoDB: Rolling back trx with id 2431, 1272 rows to undo
 
 
 
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-09-15 11:52:35 140194686691072 [Note] InnoDB: Rollback of trx with id 2431 completed
 
2017-09-15 11:52:35 7f819e7fe700  InnoDB: Rolling back trx with id 2430, 1195 rows to undo
 
 
 
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-09-15 11:52:35 140194686691072 [Note] InnoDB: Rollback of trx with id 2430 completed
 
2017-09-15 11:52:35 7f819e7fe700  InnoDB: Rolling back trx with id 2429, 1242 rows to undo
 
 
 
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-09-15 11:52:36 140194686691072 [Note] InnoDB: Rollback of trx with id 2429 completed
 
2017-09-15 11:52:36 7f819e7fe700  InnoDB: Rolling back trx with id 2428, 1163 rows to undo
 
 
 
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-09-15 11:52:36 140194686691072 [Note] InnoDB: Rollback of trx with id 2428 completed
 
2017-09-15 11:52:36 7f819e7fe700  InnoDB: Rolling back trx with id 2427, 1118 rows to undo
 
 
 
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 892017-09-15 11:52:37 140200330218432 [Note] Plugin 'FEEDBACK' is disabled.
 
2017-09-15 11:52:37 140194560833280 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2017-09-15 11:52:37 140200330218432 [Note] Recovering after a crash using tc.log
 
2017-09-15 11:52:37 140200330218432 [Note] Starting crash recovery...
 
2017-09-15 11:52:37 140200330218432 [Note] Crash recovery finished.
 
 902017-09-15 11:52:37 140200330218432 [Note] Server socket created on IP: '::'.
 
 91 92 93 94 95 96 97 98 992017-09-15 11:52:37 140200330218432 [Note] /home/a/mariadb-environs/m2-10.1/build/sql//mysqld: ready for connections.
 
Version: '10.1.27-MariaDB-debug'  socket: '/home/a/mariadb-environs/m2-10.1/dt/my.sock'  port: 3308  Source distribution
 
2017-09-15 11:52:37 140200329177856 [Note] /home/a/mariadb-environs/m2-10.1/build/sql//mysqld: Normal shutdown
 
 
 
2017-09-15 11:52:37 140200329177856 [Note] Event Scheduler: Purging the queue. 0 events
 
 1002017-09-15 11:52:37 140194686691072 [Note] InnoDB: Rollback of trx with id 2427 completed
 
2017-09-15 11:52:37 7f819e7fe700  InnoDB: Rolling back trx with id 2426, 1218 rows to undo
 
 
 
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 362017-09-15 11:52:37 140194594404096 [Note] InnoDB: FTS optimize thread exiting.
 
2017-09-15 11:52:37 140200329177856 [Note] InnoDB: Starting shutdown...
 
 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-09-15 11:52:37 140194686691072 [Note] InnoDB: Rollback of trx with id 2426 completed
 
2017-09-15 11:53:37 140200329177856 [Note] InnoDB: Waiting for 9 active transactions to finish
 
2017-09-15 11:54:37 140200329177856 [Note] InnoDB: Waiting for 9 active transactions to finish
 
2017-09-15 11:55:38 140200329177856 [Note] InnoDB: Waiting for 9 active transactions to finish
 
2017-09-15 11:56:38 140200329177856 [Note] InnoDB: Waiting for 9 active transactions to finish
 
2017-09-15 11:57:38 140200329177856 [Note] InnoDB: Waiting for 9 active transactions to finish

Comment by Andrii Nikitin (Inactive) [ 2017-09-15 ]

I it looks following mtr test can trigger the problem, but it needs more work to indicate failure by checking error log for messages 'Waiting for NN active transactions to finish' '- let me know if I should finish this test.

--source include/have_innodb.inc
 
--source include/have_sequence.inc
 
--source include/not_embedded.inc
 
 
 
let $count = 20;
 
 
 
let $c = $count;
 
while ($c)
 
{
 
  connect (con$c,localhost,root,,);
 
  eval CREATE TABLE t$c ENGINE=InnoDB select 1;
 
  start transaction;
 
  eval insert into t$c select seq from seq_1_to_10000;
 
  dec $c;
 
}
 
 
 
--connection default
 
SET GLOBAL innodb_flush_log_at_trx_commit=1;
 
create table t select 1;
 
INSERT INTO t select 1;
 
--source include/kill_and_restart_mysqld.inc
 
--let $shutdown_timeout= 900
 
--source include/restart_mysqld.inc
 
 
 
DROP TABLE t;
 
let $c = $count;
 
while ($c)
 
{
 
  eval drop table t$c;
 
  dec $c;
 
}

During the test i see in error log var/log/mysqld.1.err :

 232017-09-15 13:21:06 140543078030272 [Note] Server socket created on IP: '127.0.0.1'.
 
2017-09-15 13:21:06 140543078030272 [Note] /home/a/mariadb-environs/m2-10.1/build/sql/mysqld: ready for connections.
 
Version: '10.1.27-MariaDB-debug'  socket: '/home/a/mariadb-environs/m2-10.1/build/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
 
 24 25 26 27 282017-09-15 13:21:06 140543077071616 [Note] /home/a/mariadb-environs/m2-10.1/build/sql/mysqld: Normal shutdown
 
 
 
2017-09-15 13:21:06 140543077071616 [Note] Event Scheduler: Purging the queue. 0 events
 
2017-09-15 13:21:06 140541526255360 [Note] InnoDB: FTS optimize thread exiting.
 
2017-09-15 13:21:06 140543077071616 [Note] InnoDB: Starting shutdown...
 
 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002017-09-15 13:21:11 140541601773312 [Note] InnoDB: Rollback of trx with id 1341 completed
 
2017-09-15 13:22:07 140543077071616 [Note] InnoDB: Waiting for 19 active transactions to finish
 
2017-09-15 13:23:07 140543077071616 [Note] InnoDB: Waiting for 19 active transactions to finish
 
2017-09-15 13:24:07 140543077071616 [Note] InnoDB: Waiting for 19 active transactions to finish
 
2017-09-15 13:25:07 140543077071616 [Note] InnoDB: Waiting for 19 active transactions to finish
 
2017-09-15 13:26:07 140543077071616 [Note] InnoDB: Waiting for 19 active transactions to finish

Comment by Marko Mäkelä [ 2017-09-15 ]

anikitin, thank you for writing the test according to my suggestions. The test definitely is good enough.

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