Really slow and intensive incremental

Hi there,

I have been testing Restic, and I’ve come across an issue where the 2nd backup is as intensive and slow as the first backup. My test directory is 413GB, with 8448 directories, 150537 files.

The initial backup took something like 3 hours. During backup, CPU is close to 100% (it is a Celeron G1610T, so it’s not very powerful). After a successful initial backup (I have RESTIC_REPOSITORY and RESTIC_PASSWORD set):

D:\Tools\Restic>restic snapshots
ID Date Host Tags Directory

bdfbd30e 2017-09-08 16:54:17 piccolo D:\Data\Users

D:\Tools\Restic>restic backup D:\Data\Users
scan [D:\Data\Users]
scanned 8448 directories, 150537 files in 1:10
Interrupt received, cleaning up
[1:15] 1.08% 60.705 MiB/s 4.480 GiB / 413.317 GiB 4813 / 158985 items 0 errors ETA 1:54:57

The repository is a local USB 3 drive (U:\Restic), and the source is a local SATA hard drive. This is on Windows 2012 R2, running the latest version of Restic as of a few days ago.

As you can see, the 2nd backup is going to take almost the same amount of time as the original backup. The CPU is very high (99%), and while the backup is running, Restic is reading through all the files (I checked on the Windows Resource Monitor):

Any ideas what is going wrong?

Thanks!

Your CPU doesn’t have AES-NI, so that will definitely slow things down as far as encryption goes.

But that said I’m thinking the second backup should be quicker than the first, restic shouldn’t have to encrypt all the stuff again, right? I don’t know.

I don’t think it is encrypting, I think it is re-calculating all the source hashes to see if it needs to be backed up.

Usually restic prints using parent snapshot xxxx for second backup. In such case it’ll recalculate hashes only for changed files.

If you don’t see such message, please make sure that you’re using same path and machine doesn’t change hostname.

That’s what I also suspect, this matches the observed behavior: Restic re-reads and re-hashes all files, but does not upload anything new to the repo (because almost all data is already there). Hm, interesting case. I think this is a bug. Would you mind creating an issue in the GitHub issue tracker?

I’ve got a hunch: Can you try this (twice) with a path without d:\? I.e, run restic backup \Data\Users?

Sadly, that does not appear to change anything…

D:\>\Tools\Restic\restic.exe backup \Data\Users --repo u:\Restic
enter password for repository:
using parent snapshot bdfbd30e
scan [D:\Data\Users]
scanned 8448 directories, 150537 files in 0:10
[1:01:42] 100.00%  114.309 MiB/s  413.317 GiB / 413.317 GiB  158985 / 158985 items  0 errors  ETA 0:00
duration: 1:01:42, 114.30MiB/s
snapshot 4ad58bd9 saved

D:\>\Tools\Restic\restic.exe backup \Data\Users --repo u:\Restic
enter password for repository:
using parent snapshot 4ad58bd9
scan [D:\Data\Users]
scanned 8448 directories, 150537 files in 1:11
Interrupt received, cleaning up
[0:49] 1.05%  89.930 MiB/s  4.351 GiB / 413.317 GiB  4753 / 158985 items  0 errors  ETA 1:17:37
D:\>\Tools\Restic\restic.exe snapshots --repo u:\Restic
enter password for repository:
ID        Date                 Host        Tags        Directory
----------------------------------------------------------------------
bdfbd30e  2017-09-08 16:54:17  piccolo                 D:\Data\Users
4ad58bd9  2017-09-12 21:25:09  piccolo                 D:\Data\Users

D:\>

Hu, very strange indeed. Is there anything special regarding the system/filesystem that you use?

Would you mind recompiling restic and creating a debug log of two backup runs of a small subset of the directory?

It looks like restic detects that the files have changed since the last backup run, so it re-reads them. Hm.

I encountered similar behavior on Linux and created a new issue. I believe it’s caused by the way restic compares time when the system timezone is UTC. I wonder if the timezone on this Windows box is also UTC?

Thanks. I’ve added a comment on the issue. I don’t think it is applicable to me, as a) Windows doesn’t give you the option of setting the clock to UTC (independently of timezone), and b) although I am in the UK, it is British Summer Time (daylight savings) right now, so not at UTC anyway.

Heh, it can still be the cause for your issue. Please try again when this is corrected and then we’ll see :slight_smile:

So, the fix has been merged into the master branch, can you try again and report back?

I’ve spent an hour or so trying to get the build environment to work, but not having a lot of luck. Managed to build the docker container; it’s not in the official docker repository (why not?) so I had to figure out that I needed to download the Dockerfile first.

git clone https://github.com/restic/builder.git
cd builder
docker build -t restic/build .

Ok, now I have no idea how to download tar.gz of the source code.

cd ..
git clone https://github.com/restic/restic.git
tar -czvf restic-source.tar.gz restic/

Now when I try to run the docker build command I get this:

root@photon-machine [ ~ ]# docker run --rm --volume $PWD:/home/build restic/build restic-source.tar.gz 
/bin/bash: /usr/local/bin/build.sh: Permission denied

Any idea what else I’m doing wrong?

PS. I listened to the Go podcast this morning, fantastic interview, and great to get insight into your thought process.

Ah, interesting. I thought it was pretty clear in the manual: Install Go, clone the repo, then run go run build.go, that’s it. No need for Docker. I’m sorry for the poor user experience!

Docker is only interesting for reproducing exactly the released binaries. The Docker image used for that (repo) is online: https://hub.docker.com/r/restic/builder/ and you should be able to get it with docker [run|pull] restic/builder. It is not meant to compile anything else than a .tar.gz from an official release. So no wonder you got nowhere with giving it a tar of the restic repo checkout…

We probably need to make sure that the build.sh script in the builder container is executable. I’ll add that. Thanks for the pointer!

I’m very interested if you have any idea on how to improve the documentation!

If I click Doc (not Doc (Dev)) from the main website (https://restic.github.io/) I end up at https://restic.readthedocs.io/en/stable/, which is where I found the link for “Instructions on how to do that are contained in the builder repository”.

Downloading go now…

go run build.go --goos windows --goarch amd64

…works great (created restic.exe in the ./restic directory).

Copied it to my Windows 2012 R2 server (which is x64) and got this:

image

The following commands:

go run build.go
go run build.go --goos windows --goarch amd64

…both yield identical files, with the difference that one has .exe on the end. Given that I am running this on a Photon OS VM, that can’t be right! In other words I’m trying to run the Linux binary on a Windows machine, no wonder it doesn’t work!

-rwxr-x---  1 root root 10464864 Sep 19 13:35 restic
-rwxr-x---  1 root root 10464864 Sep 19 13:16 restic.exe

root@photon-machine [ ~/restic ]# md5sum restic
1c7c669d587b807bbb97c4ae10ac62ec  restic
root@photon-machine [ ~/restic ]# md5sum restic.exe 
1c7c669d587b807bbb97c4ae10ac62ec  restic.exe

That is odd, it works for me:


$ go run build.go

$ ./restic version
restic 0.7.2 (v0.7.2-16-ge91749bb)
compiled with go1.9 on linux/amd64

$ go run build.go --goos windows --goarch amd64

$ file restic.exe
restic.exe: PE32+ executable (console) x86-64 (stripped to external PDB), for MS Windows

$ md5sum restic*
9613b514b94484fc039a1fd772baac1e  restic
a40fa0098bdda62092205c2f2763eaf7  restic.exe

Did I do anything different?

That’s pretty amazing. Go 1.8.1 for me? I copied and pasted every command you did:

root@photon-machine [ ~/restic ]# go run build.go
root@photon-machine [ ~/restic ]# ./restic version
restic 0.7.2 (v0.7.2-16-ge91749b)
compiled with go1.8.1 on linux/amd64
root@photon-machine [ ~/restic ]# go run build.go --goos windows --goarch amd64
root@photon-machine [ ~/restic ]# file restic.exe 
restic.exe: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), statically linked, stripped
root@photon-machine [ ~/restic ]# md5sum restic*
1c7c669d587b807bbb97c4ae10ac62ec  restic
1c7c669d587b807bbb97c4ae10ac62ec  restic.exe
root@photon-machine [ ~/restic ]# 

Could it be related to Go 1.8.1?

Perhaps it is the go version. go1.9 worked for me as well.