Restic backup performance massively degraded with latest Minio build: 2017-05-05T01:14:51Z

[vsivsi]

Update: This issue has been fixed in Restic 0.6.0

---

Something changed in Minio between versions 2017-04-29T00:40:27Z and 2017-05-05T01:14:51Z that has caused Restic (version 0.5.0) backups to become incredibly slow.

@fd0 (Restic owner) should probably know about this too...

My testing has been on OS X 10.11.6.

The following table summarizes results of my repeated testing:
(Full instructions to reproduce, with output of a representative run are below)

Operation	Minio 2017-04-29	Minio 2017-05-05	Slowdown
restic init	0m1.556s	0m37.659s	24x
restic backup (inital)	0m9.221s	3m43.547s	24x
restic backup (repeat)	0m0.764s	1m12.829s	96x
restic check	0m0.785s	0m15.167s	19x
restic check --read-data	0m5.386s	0m15.002s	3x
mc mirror (to minio)	0m16.201s	0m15.938s	nil
mc mirror (from minio)	0m4.701s	0m4.300s	nil

As you can see, restic is dramatically slower with the latest minio.

Expected Behavior

Restic performance with the latest minio release would be comparable to previous versions.

Current Behavior

Many restic operations are 1-2 orders of magnitude slower after upgrading to the latest minio.

Possible Solution

¯\(ツ)/¯

Steps to Reproduce (for bugs)

The test data can be recreated by:

# 100 8MB test files with long random names, containing random data were created with:
for ((x=0;x<100;x++))
do 
   FN=$(xxd -l 32 -p -c 32 /dev/urandom)
   head -c 8000000 /dev/urandom > ~/perftest/$FN
done

Restic configuration was setup via env vars:

export AWS_ACCESS_KEY_ID= [redacted]
export AWS_SECRET_ACCESS_KEY= [redacted]
export RESTIC_PASSWORD= [redacted]
export RESTIC_REPOSITORY=s3:http://localhost:9000/perftest

Using this setup, the following tests were repeated 3 times each. The results below are representative of all of those runs:

Using previous minio release:

$ restic version
restic 0.5.0
compiled with go1.8 on darwin/amd64

$ minio version
Version: 2017-04-29T00:40:27Z
Release-Tag: RELEASE.2017-04-29T00-40-27Z
Commit-ID: 1b472dae78b491fa7efcd21278c1e6aa83b037d3 

$ mc mb myminio/perftest
Bucket created successfully `myminio/perftest`.

$ time restic init 
created restic backend 396d34517c at s3:http://localhost:9000/perftest

Please note that knowledge of your password is required to access
the repository. Losing your password means that your data is
irrecoverably lost.

real	0m1.556s
user	0m1.442s
sys	0m0.107s

$ time restic backup ~/perftest/
scan [/Users/admin/perftest]
scanned 1 directories, 100 files in 0:00
[0:08] 100.00%  90.442 MiB/s  762.939 MiB / 762.939 MiB  101 / 101 items  0 errors  ETA 0:00 
duration: 0:08, 90.42MiB/s
snapshot 33d50173 saved

real	0m9.221s
user	0m34.918s
sys	0m7.474s

$ time restic backup ~/perftest/
using parent snapshot 33d50173
scan [/Users/admin/perftest]
scanned 1 directories, 100 files in 0:00
[0:00] 100.00%  0B/s  762.939 MiB / 762.939 MiB  101 / 101 items  0 errors  ETA 0:00 
duration: 0:00, 12948.23MiB/s
snapshot 4cc8084f saved

real	0m0.764s
user	0m0.460s
sys	0m0.075s

$ time restic check
Create exclusive lock for repository
Load indexes
Check all packs
Check snapshots, trees and blobs

real	0m0.785s
user	0m0.562s
sys	0m0.109s

$ time restic check --read-data
Create exclusive lock for repository
Load indexes
Check all packs
Check snapshots, trees and blobs
Read all data
[0:04] 100.00%  156 / 156 items
duration: 0:04

real	0m5.386s
user	0m21.462s
sys	0m3.533s

$ time mc mirror ~/perftest myminio/perftest
real	0m16.201s
user	0m8.605s
sys	0m4.018s

$ time mc mirror myminio/perftest ./testmirror
real	0m4.701s
user	0m0.982s
sys	0m1.939s

Using latest minio release:

$ restic version
restic 0.5.0
compiled with go1.8 on darwin/amd64

$ minio version
Version: 2017-05-05T01:14:51Z
Release-Tag: RELEASE.2017-05-05T01-14-51Z
Commit-ID: 4f61bd025deeb1d0136d7a367f56e85877266e0e

$ mc mb myminio/perftest
Bucket created successfully `myminio/perftest`.

$ time restic init 
created restic backend f1f4277a57 at s3:http://localhost:9000/perftest

Please note that knowledge of your password is required to access
the repository. Losing your password means that your data is
irrecoverably lost.

real	0m37.659s
user	0m1.520s
sys	0m0.100s

$ time restic backup ~/perftest/
scan [/Users/admin/perftest]
scanned 1 directories, 100 files in 0:00
[3:31] 100.00%  3.616 MiB/s  762.939 MiB / 762.939 MiB  101 / 101 items  0 errors  ETA 0:00 
duration: 3:31, 3.60MiB/s
snapshot 2db252ac saved

real	3m43.547s
user	0m34.442s
sys	0m7.059s

$ time restic backup ~/perftest/
using parent snapshot 2db252ac
scan [/Users/admin/perftest]
scanned 1 directories, 100 files in 0:00
[0:59] 100.00%  12.931 MiB/s  762.939 MiB / 762.939 MiB  101 / 101 items  0 errors  ETA 0:00 
duration: 0:59, 12.80MiB/s
snapshot 82c9673e saved

real	1m12.829s
user	0m0.645s
sys	0m0.093s

$ time restic check
Create exclusive lock for repository
Load indexes
Check all packs
Check snapshots, trees and blobs

real	0m15.167s
user	0m0.730s
sys	0m0.098s

$ time restic check --read-data
Create exclusive lock for repository
Load indexes
Check all packs
Check snapshots, trees and blobs
Read all data
[0:04] 100.00%  156 / 156 items
duration: 0:04

real	0m15.002s
user	0m21.709s
sys	0m3.555s

$ time mc mirror ~/perftest myminio/perftest
real	0m15.938s
user	0m8.534s
sys	0m3.869s

$ time mc mirror myminio/perftest ./testmirror
real	0m4.300s
user	0m0.956s
sys	0m1.836s

Context

Latest minio update makes minio + restic unusable

Your Environment

OS X 10.11.6
Restic version 0.5.0 (installed with brew)
Minio version 2017-05-05T01:14:51Z (installed with brew)

Minio run as a single standalone server and accessed on localhost.

[vsivsi]

I should also note that no errors were logged to the console by either minio or restic during any of the above tests.

[krishnasrinivas]

Mostly because of 4747adf

@vsivsi we return etag during objects listing now to be more compliant with S3. I suspect that this is commit is causing the performance problem.

[harshavardhana]

Mostly because of 4747adf

@vsivsi we return etag during objects listing now to be more compliant with S3. I suspect that this is commit is causing the performance problem.

Actually this should have been represented in mc mirror as well - i think @krishnasrinivas there is a separate problem here 4747adf commit was already part of 2017-04-29T00:40:27Z release.

[harshavardhana]

I should also note that no errors were logged to the console by either minio or restic during any of the above tests.

Thanks @vsivsi attempting to reproduce locally..

[vsivsi]

@krishnasrinivas thanks for the fast response!

Based on my quick reading of the content of that commit, there must be more to it than that.

restic init literally creates two tiny files in S3. It went from 1.5s to 37.5s in the latest release. No amount of MD5 summing and JSON unmarshalling could possibly be taking 30+ seconds for a bucket containing two files, each less than a couple of KB.

Something else has to be going on.

[harshavardhana]

@krishnasrinivas thanks for the fast response!

Based on my quick reading of the content of that commit, there must be more to it than that.

restic init literally creates two tiny files in S3. It went from 1.5s to 37.5s in the latest release. No amount of MD5 summing and JSON unmarshalling could possibly be taking 30+ seconds for a bucket containing two files, each less than a couple of KB.

@vsivsi are you running FS, Erasure Code, Distributed Mode?

[harshavardhana]

also did you install from brew install minio or brew install minio/stable/minio ?

[vsivsi]

brew install minio/stable/minio

[vsivsi]

Just running a single minio instance on localhost backed by a single FS volume.

minio server ./test

[harshavardhana]

Here are my results with the new version on Linux on my laptop.

$ ./minio version
Version: 2017-05-05T01:14:51Z
Release-Tag: RELEASE.2017-05-05T01-14-51Z
Commit-ID: 40985cc4e3eec06b7ea82dc34c8d907fd2e7aa12

$ ./restic_0.5.0_linux_amd64 version
restic 0.5.0 (v0.5.0-0-gf678c97)
compiled with go1.8 on linux/amd64

$ time ./restic_0.5.0_linux_amd64 backup ~/perftest/
scan [/home/harsha/perftest]
scanned 1 directories, 100 files in 0:00
[0:05] 100.00%  145.912 MiB/s  762.939 MiB / 762.939 MiB  101 / 101 items  0 errors  ETA 0:00 
duration: 0:05, 145.84MiB/s
snapshot 8ba15ad8 saved

real	0m5.942s
user	0m15.344s
sys	0m1.864s

time ./restic_0.5.0_linux_amd64 check
Create exclusive lock for repository
Load indexes
Check all packs
Check snapshots, trees and blobs

real	0m0.732s
user	0m0.472s
sys	0m0.060s

time ./restic_0.5.0_linux_amd64 check --read-data
Create exclusive lock for repository
Load indexes
Check all packs
Check snapshots, trees and blobs
Read all data
[0:03] 100.00%  157 / 157 items
duration: 0:03

real	0m4.177s
user	0m11.460s
sys	0m1.524s

time ./restic_0.5.0_linux_amd64 backup ~/perftest/
using parent snapshot 8ba15ad8
scan [/home/harsha/perftest]
scanned 1 directories, 100 files in 0:00
[0:00] 100.00%  0B/s  762.939 MiB / 762.939 MiB  101 / 101 items  0 errors  ETA 0:00 
duration: 0:00, 37487.60MiB/s
snapshot c0a590ae saved

real	0m0.718s
user	0m0.468s
sys	0m0.036s

I am not able to reproduce the same results as yours on Linux. Is is somehow possible to access your setup?

[vsivsi]

Another clue, neither minio nor restic are using anything close to 100% CPU during the slow backups using the latest version of minio. It feels like something in minio is waiting for some kind of timeout and restic is stuck waiting for responses to its HTTP API requests.

[harshavardhana]

Oops sorry false alarm i am able to reproduce it on Linux as well @vsivsi

[vsivsi]

I'll run two tests in the morning (it's midnight here).

1. I'll try it on a different machine running MacOS Sierra.
2. I'll try it in a Linux VM or Docker on the same Mac hardware.

[harshavardhana]

Found the problem @vsivsi .. there is a retry loop that is occurring with the minio-go version restic is using.

The fix is this minio/minio-go@fd94228

[harshavardhana]

Rebuilding restic with these updates.. will keep you posted @vsivsi

[harshavardhana]

Okay so that fixed the issue,, will send a PR to restic to update minio-go.

$ time ./bin/restic init
created restic backend 8b36b544b9 at s3:http://localhost:9000/perftest

Please note that knowledge of your password is required to access
the repository. Losing your password means that your data is
irrecoverably lost.

real	0m1.196s
user	0m1.048s
sys	0m0.136s

@vsivsi - Thanks for the bug report.

[fd0]

Thanks for all the work!

[fd0]

Shall I update minio-go for restic?

[harshavardhana]

Shall I update minio-go for restic?

Either you can do, or i can do whatever is easier @fd0 .

[fd0]

I'll update it, thanks :)

[fd0]

@vsivsi Could you try again please? We've also fixed a few things for the s3 backend since v0.5.0 was released, I'll release a new version probably in the next week.

[vsivsi]

@fd0 @harshavardhana

I have confirmed that a custom build of restic master at commit restic/restic@68a9e5f solves this issue for my test cases.

Thanks for the quick response from all!

[harshavardhana]

Feel free to close this issue @vsivsi. Other we will close once Restic has released a new version.

[vsivsi]

Let's leave it open until restic releases, that way it will be easy for others to find in the meantime... Sound good?

[harshavardhana]

Good idea @vsivsi 👍

[vsivsi]

This has not yet been fixed in a restic release. Users deploying the latest released versions of minio and restic will still see this issue until that happens.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.