TokuDB Hot Backup Plugin does not release files

[Anton A. Grishin]

Hello.

I run a backup job for my Percona server with TokuDB engine as a cronjob task:

time mysql -e "SET tokudb_backup_throttle=20971520; SET tokudb_backup_dir='/var/backup/mysql'"

/var/backup/mysql - is a mount point for EBS volume

When backup job is finished I see that mysqld process does not release files in backup directory:

# tail -n2 /var/log/mysql.log
Toku Hot Backup: Finished: Mon Aug 7 19:12:18 2017

# lsof -p $(pidof mysqld) | grep "backup" | tail -n 10
mysqld 28603 mysql 2016u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 28603 mysql 2021u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 28603 mysql 2022u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 28603 mysql 2023u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 28603 mysql 2031u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 28603 mysql 2032u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 28603 mysql 2033u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 28603 mysql 2034u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 28603 mysql 2039u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 28603 mysql 2055u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par

# lsof -p $(pidof mysqld) | grep -c "backup"
852

If I delete these files, descriptors mark as deleted, what is expected:

# rm -rf /var/backup/mysql/*
# lsof -p $(pidof mysqld) | grep "backup" | tail -n 10
mysqld 28603 mysql 2016u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par (deleted)
mysqld 28603 mysql 2021u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par (deleted)
mysqld 28603 mysql 2022u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par (deleted)
mysqld 28603 mysql 2023u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par (deleted)
mysqld 28603 mysql 2031u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par (deleted)
mysqld 28603 mysql 2032u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par (deleted)
mysqld 28603 mysql 2033u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par (deleted)
mysqld 28603 mysql 2034u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par (deleted)
mysqld 28603 mysql 2039u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par (deleted)
mysqld 28603 mysql 2055u REG 202,80 112 44302937 /var/backup/mysql/mysql_data_dir/covery/normalIndex1444991622.par (deleted)

Every time I run backup job, the number of open descriptors increases until they begin to rest on the limit and backup job crashes with 'too many open files' error.
Restart of mysqld process helps to clear deleted/opened descriptors, but this is bad solution I think :)

A similar problem I found on the percona forum:
https://www.percona.com/forums/questions-discussions/third-party-tools/46438-tokudb-hot-backup-plugin-not-releasing-drive

# cat /etc/issue
Amazon Linux AMI release 2017.03
Kernel \r on an \m

# rpm -qa | grep Percona
Percona-Server-shared-57-5.7.18-15.1.el6.x86_64
Percona-Server-client-57-5.7.18-15.1.el6.x86_64
Percona-Server-tokudb-57-5.7.18-15.1.el6.x86_64
Percona-Server-server-57-5.7.18-15.1.el6.x86_64

[Nickolay Ihalainen (ihanick)]

Hi Anton,

I'm not able to reproduce the issue with single partitioned tokudb table without significant load.

Do you have file descriptors leak with tokudb_backup_dir located on same file system as mysql datadir?

Please provide the output for (during backup):
cat /proc/`pgrep -xn mysqld`/environ|xargs -0 -n 1|grep LD_PRELOAD
pt-summary
pt-mysql-summary

[Anton A. Grishin (grishin-anton)]

I have not enough free disk space on the same filesystem to create a full backup. But anyway, I decided to run a backup to monitor its behavior. It seems that the problem is reproduced even if the backups are created on the same file system as datadir:

# mount | grep mysql
/dev/nvme0n1 on /var/lib/mysql type ext4 (rw,noatime,discard,data=ordered)
/dev/xvdf on /var/backup/mysql type ext4 (rw,noatime,data=ordered)

# mysql -e "SET tokudb_backup_throttle=20971520; SET tokudb_backup_dir='/var/lib/mysql/backup'"

# mysqladmin proc| grep Back
| 528200 | root | localhost | | Query | 6107 | tokudb backup about 24% done: Backup progress 128062801636 bytes, 652 files. Throttled: copied 3462397952/7273734144 bytes of /var/lib/mysql/data/covery/finalMatchResult_key_envelopeId_createdAt_483eac0_3_1d.tokudb to /var/lib/mysql/backup/mysql_data_dir/covery/finalMatchResult_key_envelopeId_createdAt_483eac0_3_1d.tokudb. Sleeping 0.05s for throttling. | SET tokudb_backup_dir='/var/lib/mysql/backup'

# lsof -p $(pidof mysqld) | grep "/var/lib/mysql/backup/" | grep -c "\.par"
264

# lsof -p $(pidof mysqld) | grep "/var/lib/mysql/backup/" | grep "\.par" | tail
mysqld 7123 mysql *357u REG 259,0 112 25035538 /var/lib/mysql/backup/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 7123 mysql *358u REG 259,0 112 25035538 /var/lib/mysql/backup/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 7123 mysql *360u REG 259,0 112 25035538 /var/lib/mysql/backup/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 7123 mysql *361u REG 259,0 112 25035538 /var/lib/mysql/backup/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 7123 mysql *363u REG 259,0 112 25035538 /var/lib/mysql/backup/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 7123 mysql *367u REG 259,0 112 25035538 /var/lib/mysql/backup/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 7123 mysql *381u REG 259,0 112 25035538 /var/lib/mysql/backup/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 7123 mysql *382u REG 259,0 112 25035538 /var/lib/mysql/backup/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 7123 mysql *383u REG 259,0 112 25035538 /var/lib/mysql/backup/mysql_data_dir/covery/normalIndex1444991622.par
mysqld 7123 mysql *385u REG 259,0 112 25035538 /var/lib/mysql/backup/mysql_data_dir/covery/normalIndex1444991622.par

# mysqladmin kill 528200

# lsof -p $(pidof mysqld) | grep "/var/lib/mysql/backup/" | grep -c "\.par"
266

I've attached output of pt-summary and pt-mysql-summary utilities

[Anton A. Grishin (grishin-anton)]

sorry, I forgot about LD_PRELOAD:

# cat /proc/`pgrep -xn mysqld`/environ|xargs -0 -n 1|grep LD_PRELOAD
LD_PRELOAD=/usr/lib64/libjemalloc.so.1 /usr/lib64/mysql/libHotBackup.so

[Nickolay Ihalainen (ihanick)]

Hi Anton,

This bug is a duplicate, please use https://bugs.launchpad.net/percona-server/+bug/1641883 for further discussion.