xtrabackup 2.4 prepare hangs at log_reserve_and_open => log_buffer_sync_in_background

[Nickolay Ihalainen]

Could be duplicate for https://bugs.launchpad.net/percona-xtrabackup/+bug/1645774

2.3 branch was significantly faster.

Both frm and ibd files were accessed 180k times, according to strace log.
Local disks improving performance, compare to NFS (v3 or v4), but it still slower than 2.3 and pmp stack traces are the same (for local FS and NFS).

805G with 2,000 databases.

According to backup log difference in LSN is 7GB.

Last messages in log:
InnoDB: Number of pools: 1
xtrabackup: xtrabackup_logfile detected: size=8666284032, start_lsn=(9298339393850)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = .
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 8666284032
xtrabackup: using the following InnoDB configuration for recovery:
.......
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 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
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 9304593559552 (81%)
....
InnoDB: Doing recovery: scanned up to log sequence number 9306035351552 (99%)
InnoDB: Doing recovery: scanned up to log sequence number 9306040594432 (99%)
InnoDB: Doing recovery: scanned up to log sequence number 9306042739683 (99%)

        if (log_sys->buf_free + len_upper_limit > log_sys->buf_size) {
                log_mutex_exit();

                DEBUG_SYNC_C("log_buf_size_exceeded");

                /* Not enough free space, do a write of the log buffer */

                log_buffer_sync_in_background(false); // <- hangs here

Fri Jul 14 16:39:05 GMT 2017
10 pthread_cond_wait,wait(os0event.cc:165),os_event::wait_low(os0event.cc:165),os_aio_simulated_handler(os0file.cc:7968),os_aio_handler(os0file.cc:7968),fil_aio_wait(fil0fil.cc:6094),io_handler_thread(srv0start.cc:309),start_thread(libpthread.so.0),clone(libc.so.6)
1 pthread_cond_wait,wait(os0event.cc:165),os_event::wait_low(os0event.cc:165),buf_flush_page_cleaner_coordinator(buf0flu.cc:3147),start_thread(libpthread.so.0),clone(libc.so.6)
1 nanosleep(libpthread.so.0),os_thread_sleep(os0thread.cc:254),recv_writer_thread(log0recv.cc:962),start_thread(libpthread.so.0),clone(libc.so.6)
1 log_write_up_to(log0log.cc:1293),log_reserve_and_open(log0log.cc:392),mtr_t::Command::finish_write(mtr0mtr.cc:898),mtr_t::commit_checkpoint(mtr0mtr.cc:624),fil_names_clear(fil0fil.cc:7267),recv_recovery_from_checkpoint_start(log0recv.cc:4441),innobase_start_or_create_for_mysql(srv0start.cc:2186),innodb_init(xtrabackup.cc:1961),xtrabackup_prepare_func(xtrabackup.cc:7441),main(xtrabackup.cc:8321)
[<email address hidden> ~] # cat /tmp/xtrabackup-197199-dedicated02-us13.stacktrace.txt
[New LWP 59560]
[New LWP 28054]
[New LWP 28053]
[New LWP 28052]
[New LWP 28051]
[New LWP 28050]
[New LWP 28049]
[New LWP 28048]
[New LWP 28047]
[New LWP 28046]
[New LWP 28045]
[New LWP 28044]
[Thread debugging using libthread_db enabled]
0x000000000086ab68 in log_write_up_to (lsn=9471442022606, flush_to_disk=false) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/log/log0log.cc:1293
1293 {

Thread 13 (Thread 0x7f13e0ae9700 (LWP 28044)):
#0 0x0000003a3c60b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000093e4bb in wait (this=0x2246f30, reset_sig_count=1) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:165
#2 os_event::wait_low (this=0x2246f30, reset_sig_count=1) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:335
#3 0x00000000008dc4ae in os_aio_simulated_handler (segment=0, m1=0x7f13e0ae8d78, m2=0x7f13e0ae8d70, request=0x7f13e0ae8d40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:7968
#4 os_aio_handler (segment=0, m1=0x7f13e0ae8d78, m2=0x7f13e0ae8d70, request=0x7f13e0ae8d40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:6268
#5 0x000000000089bd6f in fil_aio_wait (segment=0) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/fil/fil0fil.cc:6094
#6 0x0000000000983e60 in io_handler_thread (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/srv/srv0start.cc:309
#7 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#8 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 12 (Thread 0x7f13da6e8700 (LWP 28045)):
#0 0x0000003a3c60b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000093e4bb in wait (this=0x2246fb0, reset_sig_count=2) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:165
#2 os_event::wait_low (this=0x2246fb0, reset_sig_count=2) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:335
#3 0x00000000008dc4ae in os_aio_simulated_handler (segment=1, m1=0x7f13da6e7d78, m2=0x7f13da6e7d70, request=0x7f13da6e7d40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:7968
#4 os_aio_handler (segment=1, m1=0x7f13da6e7d78, m2=0x7f13da6e7d70, request=0x7f13da6e7d40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:6268
#5 0x000000000089bd6f in fil_aio_wait (segment=1) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/fil/fil0fil.cc:6094
#6 0x0000000000983e60 in io_handler_thread (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/srv/srv0start.cc:309
#7 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#8 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 11 (Thread 0x7f13d42e7700 (LWP 28046)):
#0 0x0000003a3c60b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000093e4bb in wait (this=0x29c00f0, reset_sig_count=3864) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:165
#2 os_event::wait_low (this=0x29c00f0, reset_sig_count=3864) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:335
#3 0x00000000008dc4ae in os_aio_simulated_handler (segment=2, m1=0x7f13d42e6d78, m2=0x7f13d42e6d70, request=0x7f13d42e6d40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:7968
#4 os_aio_handler (segment=2, m1=0x7f13d42e6d78, m2=0x7f13d42e6d70, request=0x7f13d42e6d40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:6268
#5 0x000000000089bd6f in fil_aio_wait (segment=2) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/fil/fil0fil.cc:6094
#6 0x0000000000983e60 in io_handler_thread (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/srv/srv0start.cc:309
#7 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#8 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 10 (Thread 0x7f13cdee6700 (LWP 28047)):
#0 0x0000003a3c60b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000093e4bb in wait (this=0x29c0170, reset_sig_count=18856) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:165
#2 os_event::wait_low (this=0x29c0170, reset_sig_count=18856) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:335
#3 0x00000000008dc4ae in os_aio_simulated_handler (segment=3, m1=0x7f13cdee5d78, m2=0x7f13cdee5d70, request=0x7f13cdee5d40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:7968
#4 os_aio_handler (segment=3, m1=0x7f13cdee5d78, m2=0x7f13cdee5d70, request=0x7f13cdee5d40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:6268
#5 0x000000000089bd6f in fil_aio_wait (segment=3) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/fil/fil0fil.cc:6094
#6 0x0000000000983e60 in io_handler_thread (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/srv/srv0start.cc:309
#7 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#8 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 9 (Thread 0x7f13affff700 (LWP 28048)):
#0 0x0000003a3c60b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000093e4bb in wait (this=0x29c01f0, reset_sig_count=24990) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:165
#2 os_event::wait_low (this=0x29c01f0, reset_sig_count=24990) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:335
#3 0x00000000008dc4ae in os_aio_simulated_handler (segment=4, m1=0x7f13afffed78, m2=0x7f13afffed70, request=0x7f13afffed40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:7968
#4 os_aio_handler (segment=4, m1=0x7f13afffed78, m2=0x7f13afffed70, request=0x7f13afffed40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:6268
#5 0x000000000089bd6f in fil_aio_wait (segment=4) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/fil/fil0fil.cc:6094
#6 0x0000000000983e60 in io_handler_thread (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/srv/srv0start.cc:309
#7 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#8 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 8 (Thread 0x7f13a3fff700 (LWP 28049)):
#0 0x0000003a3c60b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000093e4bb in wait (this=0x29c0270, reset_sig_count=20845) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:165
#2 os_event::wait_low (this=0x29c0270, reset_sig_count=20845) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:335
#3 0x00000000008dc4ae in os_aio_simulated_handler (segment=5, m1=0x7f13a3ffed78, m2=0x7f13a3ffed70, request=0x7f13a3ffed40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:7968
#4 os_aio_handler (segment=5, m1=0x7f13a3ffed78, m2=0x7f13a3ffed70, request=0x7f13a3ffed40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:6268
#5 0x000000000089bd6f in fil_aio_wait (segment=5) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/fil/fil0fil.cc:6094
#6 0x0000000000983e60 in io_handler_thread (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/srv/srv0start.cc:309
#7 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#8 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 7 (Thread 0x7f1397fff700 (LWP 28050)):
#0 0x0000003a3c60b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000093e4bb in wait (this=0x29c02f0, reset_sig_count=28) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:165
#2 os_event::wait_low (this=0x29c02f0, reset_sig_count=28) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:335
#3 0x00000000008dc4ae in os_aio_simulated_handler (segment=6, m1=0x7f1397ffed78, m2=0x7f1397ffed70, request=0x7f1397ffed40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:7968
#4 os_aio_handler (segment=6, m1=0x7f1397ffed78, m2=0x7f1397ffed70, request=0x7f1397ffed40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:6268
#5 0x000000000089bd6f in fil_aio_wait (segment=6) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/fil/fil0fil.cc:6094
#6 0x0000000000983e60 in io_handler_thread (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/srv/srv0start.cc:309
#7 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#8 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 6 (Thread 0x7f138bfff700 (LWP 28051)):
#0 0x0000003a3c60b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000093e4bb in wait (this=0x29c0370, reset_sig_count=132) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:165
#2 os_event::wait_low (this=0x29c0370, reset_sig_count=132) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:335
#3 0x00000000008dc4ae in os_aio_simulated_handler (segment=7, m1=0x7f138bffed78, m2=0x7f138bffed70, request=0x7f138bffed40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:7968
#4 os_aio_handler (segment=7, m1=0x7f138bffed78, m2=0x7f138bffed70, request=0x7f138bffed40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:6268
#5 0x000000000089bd6f in fil_aio_wait (segment=7) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/fil/fil0fil.cc:6094
#6 0x0000000000983e60 in io_handler_thread (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/srv/srv0start.cc:309
#7 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#8 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 5 (Thread 0x7f137ffff700 (LWP 28052)):
#0 0x0000003a3c60b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000093e4bb in wait (this=0x29c03f0, reset_sig_count=106) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:165
#2 os_event::wait_low (this=0x29c03f0, reset_sig_count=106) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:335
#3 0x00000000008dc4ae in os_aio_simulated_handler (segment=8, m1=0x7f137fffed78, m2=0x7f137fffed70, request=0x7f137fffed40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:7968
#4 os_aio_handler (segment=8, m1=0x7f137fffed78, m2=0x7f137fffed70, request=0x7f137fffed40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:6268
#5 0x000000000089bd6f in fil_aio_wait (segment=8) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/fil/fil0fil.cc:6094
#6 0x0000000000983e60 in io_handler_thread (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/srv/srv0start.cc:309
#7 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#8 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 4 (Thread 0x7f1379bfe700 (LWP 28053)):
#0 0x0000003a3c60b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000093e4bb in wait (this=0x29c0470, reset_sig_count=118) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:165
#2 os_event::wait_low (this=0x29c0470, reset_sig_count=118) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:335
#3 0x00000000008dc4ae in os_aio_simulated_handler (segment=9, m1=0x7f1379bfdd78, m2=0x7f1379bfdd70, request=0x7f1379bfdd40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:7968
#4 os_aio_handler (segment=9, m1=0x7f1379bfdd78, m2=0x7f1379bfdd70, request=0x7f1379bfdd40) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0file.cc:6268
#5 0x000000000089bd6f in fil_aio_wait (segment=9) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/fil/fil0fil.cc:6094
#6 0x0000000000983e60 in io_handler_thread (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/srv/srv0start.cc:309
#7 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#8 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 3 (Thread 0x7f136bfff700 (LWP 28054)):
#0 0x0000003a3c60b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000093e4bb in wait (this=0x56f0cc0, reset_sig_count=32110) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:165
#2 os_event::wait_low (this=0x56f0cc0, reset_sig_count=32110) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0event.cc:335
#3 0x000000000097bb76 in buf_flush_page_cleaner_coordinator (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/buf/buf0flu.cc:3147
#4 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#5 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 2 (Thread 0x7f134ffff700 (LWP 59560)):
#0 0x0000003a3c60f00d in nanosleep () from /lib64/libpthread.so.0
#1 0x0000000000893150 in os_thread_sleep (tm=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/os/os0thread.cc:254
#2 0x000000000088a033 in recv_writer_thread (arg=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/log/log0recv.cc:962
#3 0x0000003a3c607aa1 in start_thread () from /lib64/libpthread.so.0
#4 0x0000003a3c2e893d in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x7f14237067e0 (LWP 28004)):
#0 0x000000000086ab68 in log_write_up_to (lsn=9471442022606, flush_to_disk=false) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/log/log0log.cc:1293
#1 0x000000000086caf3 in log_reserve_and_open (len=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/log/log0log.cc:392
#2 0x00000000008905bd in mtr_t::Command::finish_write (this=0x7fff00d068e0, len=941660) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/mtr/mtr0mtr.cc:898
#3 0x0000000000891a38 in mtr_t::commit_checkpoint (this=<value optimized out>, checkpoint_lsn=9465801873993) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/mtr/mtr0mtr.cc:624
#4 0x00000000008987b1 in fil_names_clear (lsn=9465801873993, do_write=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/fil/fil0fil.cc:7267
#5 0x000000000088ea12 in recv_recovery_from_checkpoint_start (flush_lsn=140733207053960) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/log/log0recv.cc:4441
#6 0x000000000098a491 in innobase_start_or_create_for_mysql () at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/srv/srv0start.cc:2186
#7 0x0000000000734359 in innodb_init () at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/xtrabackup/src/xtrabackup.cc:1961
#8 0x0000000000741c7d in xtrabackup_prepare_func () at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/xtrabackup/src/xtrabackup.cc:7441
#9 0x000000000074588d in main (argc=<value optimized out>, argv=<value optimized out>) at /usr/src/debug/percona-xtrabackup-2.4.7/storage/innobase/xtrabackup/src/xtrabackup.cc:8321

[Nickolay Ihalainen (ihanick)]

Steps to reproduce:
hardware:
single sata HDD.
CPU 8x core amd, but it's not important cpu usage is small.

Generate dataset:
for i in `seq 1000000` ; do echo "create table t$i (id int auto_increment, primary key(id)) engine=innodb;insert into t1 values (),();" ; done > create_tables.sql

load database to mysql 5.7 ( start mysqld under libeatmydata to make it fast, about 15 minutes)

Insert some rows to mysql:
import os
import random
import mysql.connector
cnx = mysql.connector.connect(user='root', database='test')
cursor = cnx.cursor()

for i in range(10000):
  query = "INSERT t{0} VALUES()".format(random.randrange(1, 1000000, 1))
  cursor.execute(query)
  cnx.commit()

cursor.close()
cnx.close()

Backup database (it's lasts forever without parallel, )
time xtrabackup --backup --skip-tables-compatibility-check --parallel=8
xtrabackup: Transaction log of lsn (7804802029) to (11939776928) was copied.
170831 00:26:42 completed OK!

real 8498m53.610s
user 18m42.898s
sys 34m25.394s

Unprepared backup requires 100GB on disk (2GB compressed to tar.gz I can share unprepared backup).

It's interesting that offline backup 144X times faster than xtrabackup without prepare:
time tar czf xtrabackup_backupfiles.tar.gz xtrabackup_backupfiles
real 58m51.506s
user 24m5.608s
sys 8m1.729s

xtrabackup --prepare --use-memory=8G --target-dir=/root/xtrabackup_backupfiles
hangs for at least 8 hours after:
InnoDB: Doing recovery: scanned up to log sequence number 11939776928 (88%)
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.

Killed xtrabackup restarted with and in one hour passed that point:
xtrabackup --prepare --use-memory=8G --innodb_log_buffer_size=64M --target-dir=/root/xtrabackup_backupfiles

InnoDB: Doing recovery: scanned up to log sequence number 11939776928 (88%)
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8

[Sergei Glushchenko (sergei.glushchenko)]

I think it is not fair to compare xtrabackup backup of MySQL server when it is under heavy write load on HDD and offline tar compressed backup when no other IO is done. More fair would be to compare xtrabackup backup of server under heavy load with uncompressed tar backup of mysql datadir under the same load. Though tar would still have advantage because it doesn't calculate checksums and copies less redo logs.

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-xtrabackup/pull/445

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXB-506