LP #1709495: XtraBackup stuck in prepare stage waiting for pending reads

**Reported in Launchpad by Ovais Tariq last update 19-01-2018 01:16:16

PXB version
/usr/bin/xtrabackup version 2.4.7 based on MySQL server 5.7.13 Linux (x86_64) (revision id: 05f1fcf)

PXB log entries
xtrabackup: cd to /var/lib/mysql/
xtrabackup: This target seems to be not prepared yet.
InnoDB: Number of pools: 1
xtrabackup: xtrabackup_logfile detected: size=1449263104, start_lsn=(14747305820062)
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 = 1449263104
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 = 1449263104
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 37133221888 bytes for buffer pool (set by --use-memory parameter)
InnoDB: PUNCH HOLE support available
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Uses event mutexes
InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
InnoDB: Compressed tables use zlib 1.2.8
InnoDB: Number of pools: 1
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, total size = 34.625G, instances = 1, chunk size = 128M
InnoDB: Completed initialization of buffer pool
InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 14747305820062
InnoDB: Doing recovery: scanned up to log sequence number 14747311062528 (0%)
InnoDB: Doing recovery: scanned up to log sequence number 14747316305408 (0%)
InnoDB: Doing recovery: scanned up to log sequence number 14747321548288 (1%)
InnoDB: Doing recovery: scanned up to log sequence number 14747326791168 (1%)
...
InnoDB: Doing recovery: scanned up to log sequence number 14748593339904 (99%)
InnoDB: Doing recovery: scanned up to log sequence number 14748594007176 (99%)
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 InnoDB: Waited for 10 seconds for 128 pending reads
InnoDB: Waited for 20 seconds for 128 pending reads
InnoDB: Waited for 30 seconds for 128 pending reads
InnoDB: Waited for 40 seconds for 128 pending reads
InnoDB: Waited for 50 seconds for 128 pending reads
InnoDB: Waited for 60 seconds for 128 pending reads
InnoDB: Waited for 70 seconds for 128 pending reads
InnoDB: Waited for 80 seconds for 128 pending reads
InnoDB: Waited for 90 seconds for 128 pending reads
InnoDB: Waited for 100 seconds for 128 pending reads
...
InnoDB: Waited for 93730 seconds for 128 pending reads
InnoDB: Waited for 93740 seconds for 128 pending reads
InnoDB: Waited for 93750 seconds for 128 pending reads
InnoDB: Waited for 93760 seconds for 128 pending reads
InnoDB: Waited for 93770 seconds for 128 pending reads

And then it just keeps waiting on the pending reads until PXB is killed.

We hit a similar bug in PS sometime ago where the pending reads would not finish and we ended up using innodb_empty_free_list_algorithm=legacy to fix the problem:
https://github.com/uber/percona-server/pull/2