[MDEV-13797] InnoDB may hang if shutdown is initiated soon after startup, while rolling back recovered incomplete transactions - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
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
Component/s: Backup, Storage Engine - InnoDB, Storage Engine - XtraDB
Labels:
- backup
- hang
- innodb
- recovery
- shutdown

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

Attachments

Issue Links

is caused by

MDEV-12091 Shutdown fails to wait for rollback of recovered transactions to finish

Closed

is duplicated by

MDEV-13808 (draft) possible hang on shutdown

Closed

relates to

MDEV-12323 Rollback progress log messages during crash recovery are intermixed with unrelated log messages

Closed

MDEV-13807 mariabackup --apply-log-only does generate redo log by performing rollback and possibly other tasks

Closed

Activity

Ascending order - Click to sort in descending order

Marko Mäkelä added a comment - 2017-09-14 11:07 - edited

I see the following problems:

--apply-log-only is not preventing the rollback from happening (~~MDEV-13807~~)
the rollback progress reporting is inadequate (~~MDEV-12323~~)
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:

Start a number of transactions that modify data.
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.
Kill the server.
Restart and quickly shut down the server. It should hang on shutdown.

Marko Mäkelä added a comment - 2017-09-14 11:07 - edited I see the following problems: --apply-log-only is not preventing the rollback from happening ( MDEV-13807 ) the rollback progress reporting is inadequate ( MDEV-12323 ) 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: Start a number of transactions that modify data. 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. Kill the server. Restart and quickly shut down the server. It should hang on shutdown.

Andrii Nikitin (Inactive) added a comment - 2017-09-15 09:05 - edited

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

Andrii Nikitin (Inactive) added a comment - 2017-09-15 09:05 - edited 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

Andrii Nikitin (Inactive) added a comment - 2017-09-15 10:01 - edited

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

Andrii Nikitin (Inactive) added a comment - 2017-09-15 10:01 - edited 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

Andrii Nikitin (Inactive) added a comment - 2017-09-15 11:34

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

Andrii Nikitin (Inactive) added a comment - 2017-09-15 11:34 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

Marko Mäkelä added a comment - 2017-09-15 13:22

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

Marko Mäkelä added a comment - 2017-09-15 13:22 anikitin , thank you for writing the test according to my suggestions. The test definitely is good enough.

People

Assignee:: Marko Mäkelä

Reporter:: Geoff Montee (Inactive)

Votes:: 1 Vote for this issue

Watchers:: 7 Start watching this issue

Dates

Created:: 2017-09-13 17:00

Updated:: 2024-07-08 00:38

Resolved:: 2017-12-13 14:33

Git Integration

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

MariaDB Server