Really slow and intensive incremental

I don’t think so. Setting the environment variables GOARCH and GOOS for cross-compilation worked flawlessly since Go 1.5 or so (that’s what build.go does internally).

Please try the following: Create a new file:

package main
import "fmt"
func main() {
        fmt.Println("test")
}

Then run:

$ GOOS=windows GOARCH=amd64 go build -o main.exe main.go

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

I suspect that the command go does something unexpected on your system and does not pass on the GOARCH and GOOS environment variables.

Where did you get the version of Go you’re using? Go 1.8.1 is rather old (1.8.3 or 1.9 are the current versions).

Thanks, I appreciate the patience here…

root@photon-machine [ ~ ]# GOOS=windows GOARCH=amd64 go build -o main.exe main.go 
root@photon-machine [ ~ ]# file main.exe
main.exe: PE32+ executable (console) x86-64 (stripped to external PDB), for MS Windows

Ok, that looks good. Honestly, I have no idea what’s going on here. That’s basically what build.go does: Copy all the files to a temporary directory, set the environment variables and call go build with them in the temporary directory.

Any other ideas what’s going on?

It’s VMware Photon (a purpose built extremely tiny Linux image optimised for VMware), and Go comes from TDNF (a yum clone?) which is how Photon is updated, probably from this repo (no idea who bintray is):

root@photon-machine [ ~ ]# cat /etc/yum.repos.d/photon-extras.repo 
[photon-extras]
name=VMware Photon Extras 1.0(x86_64)
baseurl=https://dl.bintray.com/vmware/photon_extras
gpgkey=file:///etc/pki/rpm-gpg/VMWARE-RPM-GPG-KEY
gpgcheck=1
enabled=1
skip_if_unavailable=True

root@photon-machine [ ~ ]# ls -la /etc/yum.repos.d/                   
total 32
drwxr-xr-x  2 root root 4096 Sep 19 18:22 .
drwxr-xr-x 33 root root 4096 Sep 19 13:17 ..
-rw-r--r--  1 root root  190 Jun  7  2016 lightwave.repo
-rw-r--r--  1 root root  239 Jun  7  2016 photon-debuginfo.repo
-rw-r--r--  1 root root  202 Jun  7  2016 photon-extras.repo
-rw-r--r--  1 root root  181 Jun  7  2016 photon-iso.repo
-rw-r--r--  1 root root  232 Jun  7  2016 photon-updates.repo
-rw-r--r--  1 root root  217 Jun  7  2016 photon.repo

You could try with the official Go version (1.9 is best): Download it from https://golang.org/dl/, extract it somewhere, then call $DIR/bin/go with build.go as usual.

By the way: You can also do that on Windows, no Linux required…

Yes! In the end I didn’t have enough time to compile my own restic, but 0.7.3 was released and it looks like it has the fix. Excellent stuff!

D:\Tools\Restic>restic_0.7.3_windows_amd64.exe version
restic 0.7.3
compiled with go1.9 on windows/amd64

D:\Tools\Restic>restic_0.7.3_windows_amd64.exe backup D:\Data\Users --repo U:\Restic
enter password for repository:
using parent snapshot 4ad58bd9
scan [D:\Data\Users]
scanned 8448 directories, 150537 files in 0:04
[1:53] 100.00%  3.547 GiB/s  413.317 GiB / 413.317 GiB  158985 / 158985 items  0 errors  ETA 0:03
duration: 1:53, 3719.69MiB/s
snapshot c937d9e8 saved
1 Like

Great, that looks much better indeed :slight_smile:

1 Like

Seeing this problem here on Linux, running the latest restic from git:

debug enabled
restic 0.8.1 (v0.8.1-15-g2bc4d200)
compiled with go1.9.2 on linux/amd64

Just finished an initial snapshot of my whole filesystem to Backblaze B2:

$ restic backup --limit-upload=5000 --cache-dir=/var/cache/restic/moria/ --one-file-system --exclude-file=/etc/restic/moria/backup.exclude --exclude=/var/cache/* --exclude=/tmp/* --exclude=/var/tmp/* --exclude=/home/*/.cache/* --exclude=/run/* /
debug log file /var/log/private/restic/moria/debug.log
debug enabled
password is correct
scan [/]
scanned 104616 directories, 784437 files in 8:50
[4:21:52] 99.99%  12.155 MiB/s  186.505 GiB / 186.517 GiB  889049 / 889053 items  0 errors  ETA 0:01 
duration: 4:21:52, 12.16MiB/s
snapshot 88b95a4d saved

Now I immediately started it again, but instead of just running the initial scan + possible uploading a few KiB/MiB of recent changes since then, it seems to re-calculate the hashes for the whole filesystem (no upload activity during this time):

$ restic backup --limit-upload=5000 --cache-dir=/var/cache/restic/moria/ --one-file-system --exclude-file=/etc/restic/moria/backup.exclude --exclude=/var/cache/* --exclude=/tmp/* --exclude=/var/tmp/* --exclude=/home/*/.cache/* --exclude=/run/* /
debug log file /var/log/private/restic/moria/debug.log
debug enabled
password is correct
using parent snapshot 88b95a4d
scan [/]
scanned 104617 directories, 784434 files in 8:46
warning for /home/elias/.local/share/sddm/xorg-session.log: expected 9467684282 bytes, saved 9467684403 bytes
[1:18:48] 60.05%  24.287 MiB/s  112.137 GiB / 186.740 GiB  329351 / 889051 items  0 errors  ETA 52:25 

Unfortunately, the debug.log grew too large and filled up my remaining free space, so I had to truncate -s10M debug.log it. Will try to reduce verbosity for the next run or free up some more space to be able to provide valuable debug information.

What I’m currently seeing it when tail-ing it, is stuff like this:

2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2574    id ef6633bf not found
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2566    id 9913ca9d not found
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2574    id ef6633bf not found
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2566    id 9913ca9d not found
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2574    id ef6633bf not found
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2566    id 9913ca9d not found
2018/01/05 14:59:15 archiver/archiver.go:545    archiver.(*archivePipe).compare 2542    old job: home/elias/code-repositories/public/gentoo/repositories/gentoo/dev-texlive/texlive-documentation-mongolian/metadata.xml
2018/01/05 14:59:15 archiver/archiver.go:546    archiver.(*archivePipe).compare 2542    new job: home/elias/code-repositories/public/gentoo/repositories/gentoo/dev-texlive/texlive-documentation-mongolian/metadata.xml
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2574    id ef6633bf not found
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2566    id 9913ca9d not found
2018/01/05 14:59:15 archiver/archiver.go:556    archiver.(*archivePipe).compare 2542        same filename "home/elias/code-repositories/public/gentoo/repositories/gentoo/dev-texlive/texlive-documentation-mongolian/metadata.xml"
2018/01/05 14:59:15 archiver/archiver.go:597    archiver.archiveJob.Copy        2542       job home/elias/code-repositories/public/gentoo/repositories/gentoo/dev-texlive/texlive-documentation-mongolian/metadata.xml is file
2018/01/05 14:59:15 restic/exclude.go:226       main.rejectByDevice.func1       2541    item /home/elias/code-repositories/public/gentoo/repositories/gentoo/dev-texlive/texlive-documentation-mongolian/texlive-documentation-mongolian-2012.ebuild, test dir /home/elias/code-repositories/public/gentoo/repositories/gentoo/dev-texlive/texlive-documentation-mongolian
2018/01/05 14:59:15 restic/node.go:555  restic.(*Node).IsNewer  2542    node /home/elias/code-repositories/public/gentoo/repositories/gentoo/dev-texlive/texlive-documentation-mongolian/metadata.xml is not newer
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2570    id 970a7ce9 not found
2018/01/05 14:59:15 archiver/archiver.go:610    archiver.archiveJob.Copy        2542       job home/elias/code-repositories/public/gentoo/repositories/gentoo/dev-texlive/texlive-documentation-mongolian/metadata.xml add old data
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2570    id 970a7ce9 not found
2018/01/05 14:59:15 restic/exclude.go:226       main.rejectByDevice.func1       2541    item /home/elias/code-repositories/public/gentoo/repositories/gentoo/dev-texlive/texlive-documentation-mongolian/texlive-documentation-mongolian-2012.ebuild, test dir /home/elias/code-repositories/public/gentoo/repositories/gentoo/dev-texlive
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2570    id 970a7ce9 not found
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2574    id ef6633bf not found
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2576    id 1e17e09a not found
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2570    id 970a7ce9 not found
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2574    id ef6633bf not found
2018/01/05 14:59:15 repository/index.go:142     repository.(*Index).Lookup      2570    id 970a7ce9 not found

Hey, I think you’ve run into a variant of issue #1290.

Can you please try passing restic /* instead of /? So the command line is restic backup [...] /* instead of restic backup [...] /?

Please report back!

Giving it a try, hoping --one-file-system overrides /* which would also expand to include /sys, /proc, /dev etc. :slight_smile:

Yes it does, that should work.

Two issues:

  1. It didn’t seem to work - it finished the scan in 8:49 and now again started calculating hashes…
  2. I noticed in my debug.log that it actually seems to scan excluded files such as /proc/21186/task/21245/environ:
    2018/01/05 17:22:08 restic/exclude.go:226       main.rejectByDevice.func1       1       item /proc/21186/task/21245/environ, test dir /proc/21186
    

Information:

Command used:

restic backup --limit-upload=5000 --cache-dir=/var/cache/restic/moria/ --one-file-system --exclude-file=/etc/restic/moria/backup.exclude --exclude=/var/cache/* --exclude=/tmp/* --exclude=/var/tmp/* --exclude=/home/*/.cache/* --exclude=/run/* /*

Environment variables:

RESTIC_PASSWORD=##redacted##
RESTIC_REPOSITORY=b2:backup-moria
B2_ACCOUNT_ID=##redacted##
B2_ACCOUNT_KEY=##redacted##
DEBUG_LOG=/var/log/private/restic/moria/debug.log
TMPDIR=/var/log/private/restic/moria

Content of /etc/restic/moria/backup.exclude:

/home/elias/.cache/*
/home/elias/.cargo
/home/elias/Steam
/nix
/usr/lib/debug/*
/usr/lib64/debug/*
/usr/share/texmf-dist
/usr/src/*
/var/cache/*
/var/lib/docker
/var/log/*
/var/swap.img
/var/tmp/*

Ah, that’s a bummer. I still think it’s a variant of #1290. Would you like to run more tests in order to find out what’s going on? If so, the next step would be to play around with the backup target paths a bit more:

  • Backup only a (small) single dir /home, then run a subsequent backup. The second backup should not read the files and be very fast
  • Backup two dirs, e.g. /home and /etc, that should be slow on the first, and fast on the second backup.
  • This way, slowly work your way up to what /* expands to, make a note when the second backup in each step is slow too.

By the way, the effect that you’re observing is independent of the backend, you could also use a local (or sftp) backend if you have the space locally.

Hm, maybe we can still tune that a bit more. I’d need to dig into the details to find out what’s going on here. The debug message is about that the file is to be excluded because it’s not on one of the allowed file systems (so the exclude is by --one-file-system, but it shouldn’t need to traverse the dir, because /proc/21186 should already have been excluded. Hm.

Didn’t get around to this yet - will hopefully find some time during the next days to look into this.

The problem here seems to be, that the expansion of /* includes excluded paths again (the ones excluded by --one-file-system as well those excluded by --exclude= or --exclude-file), as also indicated by this output line:

scan [/bin /boot /dev /etc /home /lib /lib32 /lib64 /lost+found /media /nix /opt /proc /root /run /sbin /srv /sys /tmp /usr /var]

e.g.:
/dev or /proc - should be excluded by --one-file-system
/nix - should be excluded by the line /nix in the file referenced by --exclude-file=/etc/restic/moria/backup.exclude

For /tmp it’s reasonable to appear and for the directory itself to be scanned (but not its content):

  • it was included by the expansion of /*
  • only its sub-items are excluded by --exclude=/tmp/*
  • it’s a separate filesystem (tmpfs), but this also doesn’t apply to /tmp itself, but only sub-items

Ah, don’t worry about the scan line, it’ll just show what you pass restic backup in verbatim, the exclusion logic happens later. I’m sure that e.g. /dev and /proc are still excluded.