From 973fa921cb6bb19de6233532e1100bf779908d28 Mon Sep 17 00:00:00 2001 From: greatroar <@> Date: Thu, 20 Feb 2020 11:56:33 +0100 Subject: [PATCH 01/12] Test and document Restorer.VerifyFiles --- internal/restorer/restorer.go | 5 ++++- internal/restorer/restorer_test.go | 8 ++++++++ 2 files changed, 12 insertions(+), 1 deletion(-) diff --git a/internal/restorer/restorer.go b/internal/restorer/restorer.go index 75ed99f86..b87a8a6f7 100644 --- a/internal/restorer/restorer.go +++ b/internal/restorer/restorer.go @@ -310,7 +310,10 @@ func (res *Restorer) Snapshot() *restic.Snapshot { return res.sn } -// VerifyFiles reads all snapshot files and verifies their contents +// VerifyFiles checks whether all regular files in the snapshot res.sn +// have been successfully written to dst. It stops when it encounters an +// error. It returns that error and the number of files it has checked, +// including the file(s) that caused errors. func (res *Restorer) VerifyFiles(ctx context.Context, dst string) (int, error) { // TODO multithreaded? diff --git a/internal/restorer/restorer_test.go b/internal/restorer/restorer_test.go index 32be0f51d..4a51c2c19 100644 --- a/internal/restorer/restorer_test.go +++ b/internal/restorer/restorer_test.go @@ -367,6 +367,11 @@ func TestRestorer(t *testing.T) { t.Fatal(err) } + if len(test.ErrorsMust)+len(test.ErrorsMay) == 0 { + _, err = res.VerifyFiles(ctx, tempdir) + rtest.OK(t, err) + } + for location, expectedErrors := range test.ErrorsMust { actualErrors, ok := errors[location] if !ok { @@ -465,6 +470,9 @@ func TestRestorerRelative(t *testing.T) { if err != nil { t.Fatal(err) } + nverified, err := res.VerifyFiles(ctx, "restore") + rtest.OK(t, err) + rtest.Equals(t, len(test.Files), nverified) for filename, err := range errors { t.Errorf("unexpected error for %v found: %v", filename, err) From 92ae951ffafff396f748a096946f43639d37a60f Mon Sep 17 00:00:00 2001 From: greatroar <@> Date: Thu, 20 Feb 2020 21:54:31 +0100 Subject: [PATCH 02/12] Report timing from restic restore --verify --- cmd/restic/cmd_restore.go | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/cmd/restic/cmd_restore.go b/cmd/restic/cmd_restore.go index cbab2bed4..0ece13e5f 100644 --- a/cmd/restic/cmd_restore.go +++ b/cmd/restic/cmd_restore.go @@ -2,6 +2,7 @@ package main import ( "strings" + "time" "github.com/restic/restic/internal/debug" "github.com/restic/restic/internal/errors" @@ -202,6 +203,7 @@ func runRestore(opts RestoreOptions, gopts GlobalOptions, args []string) error { if opts.Verify { Verbosef("verifying files in %s\n", opts.Target) var count int + t0 := time.Now() count, err = res.VerifyFiles(ctx, opts.Target) if err != nil { return err @@ -209,7 +211,8 @@ func runRestore(opts RestoreOptions, gopts GlobalOptions, args []string) error { if totalErrors > 0 { return errors.Fatalf("There were %d errors\n", totalErrors) } - Verbosef("finished verifying %d files in %s\n", count, opts.Target) + Verbosef("finished verifying %d files in %s (took %s)\n", count, opts.Target, + time.Since(t0).Round(time.Millisecond)) } return nil From 556424d61ba8be128b85de8c53a58ebe8ddb5f18 Mon Sep 17 00:00:00 2001 From: greatroar <@> Date: Thu, 20 Feb 2020 22:43:56 +0100 Subject: [PATCH 03/12] Reuse buffer in Restorer.VerifyFiles Time to verify a 2GB snapshot down from 11.568s to 9.726s (-16%). --- internal/restorer/restorer.go | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/internal/restorer/restorer.go b/internal/restorer/restorer.go index b87a8a6f7..938be2b44 100644 --- a/internal/restorer/restorer.go +++ b/internal/restorer/restorer.go @@ -5,6 +5,7 @@ import ( "os" "path/filepath" + "github.com/restic/chunker" "github.com/restic/restic/internal/errors" "github.com/restic/restic/internal/debug" @@ -316,8 +317,11 @@ func (res *Restorer) Snapshot() *restic.Snapshot { // including the file(s) that caused errors. func (res *Restorer) VerifyFiles(ctx context.Context, dst string) (int, error) { // TODO multithreaded? + var ( + buf = make([]byte, 0, chunker.MaxSize) + count = 0 + ) - count := 0 _, err := res.traverseTree(ctx, dst, string(filepath.Separator), *res.sn.Tree, treeVisitor{ enterDir: func(node *restic.Node, target, location string) error { return nil }, visitNode: func(node *restic.Node, target, location string) error { @@ -342,7 +346,7 @@ func (res *Restorer) VerifyFiles(ctx context.Context, dst string) (int, error) { offset := int64(0) for _, blobID := range node.Content { length, _ := res.repo.LookupBlobSize(blobID, restic.DataBlob) - buf := make([]byte, length) // TODO do I want to reuse the buffer somehow? + buf = buf[:length] _, err = file.ReadAt(buf, offset) if err != nil { _ = file.Close() From bb066cf7d3ac1ff2a71ac8c1f178eb9c95b16d2c Mon Sep 17 00:00:00 2001 From: greatroar <@> Date: Thu, 20 Feb 2020 11:38:44 +0100 Subject: [PATCH 04/12] Concurrent Restorer.VerifyFiles Time to verify a 2GB snapshot down from 9.726s to 4.645s (-52%). --- changelog/unreleased/pull-2594 | 7 ++ internal/restorer/restorer.go | 139 +++++++++++++++++++++++---------- 2 files changed, 103 insertions(+), 43 deletions(-) create mode 100644 changelog/unreleased/pull-2594 diff --git a/changelog/unreleased/pull-2594 b/changelog/unreleased/pull-2594 new file mode 100644 index 000000000..516dc50da --- /dev/null +++ b/changelog/unreleased/pull-2594 @@ -0,0 +1,7 @@ +Enhancement: Speed up restic restore --verify + +The --verify option causes restic restore to do some verification after it +has restored from a snapshot. This verification now runs up to 52% faster, +depending on the exact setup. + +https://github.com/restic/restic/pull/2594 diff --git a/internal/restorer/restorer.go b/internal/restorer/restorer.go index 938be2b44..60f9dc022 100644 --- a/internal/restorer/restorer.go +++ b/internal/restorer/restorer.go @@ -4,13 +4,14 @@ import ( "context" "os" "path/filepath" - - "github.com/restic/chunker" - "github.com/restic/restic/internal/errors" + "sync/atomic" "github.com/restic/restic/internal/debug" + "github.com/restic/restic/internal/errors" "github.com/restic/restic/internal/fs" "github.com/restic/restic/internal/restic" + + "golang.org/x/sync/errgroup" ) // Restorer is used to restore a snapshot to a directory. @@ -311,58 +312,110 @@ func (res *Restorer) Snapshot() *restic.Snapshot { return res.sn } +// Number of workers in VerifyFiles. +const nVerifyWorkers = 8 + // VerifyFiles checks whether all regular files in the snapshot res.sn // have been successfully written to dst. It stops when it encounters an // error. It returns that error and the number of files it has checked, // including the file(s) that caused errors. func (res *Restorer) VerifyFiles(ctx context.Context, dst string) (int, error) { - // TODO multithreaded? + type mustCheck struct { + node *restic.Node + path string + } + var ( - buf = make([]byte, 0, chunker.MaxSize) - count = 0 + nchecked uint64 + work = make(chan mustCheck, 2*nVerifyWorkers) ) - _, err := res.traverseTree(ctx, dst, string(filepath.Separator), *res.sn.Tree, treeVisitor{ - enterDir: func(node *restic.Node, target, location string) error { return nil }, - visitNode: func(node *restic.Node, target, location string) error { - if node.Type != "file" { - return nil - } + g, ctx := errgroup.WithContext(ctx) - count++ - stat, err := os.Stat(target) - if err != nil { - return err - } - if int64(node.Size) != stat.Size() { - return errors.Errorf("Invalid file size: expected %d got %d", node.Size, stat.Size()) - } + // Traverse tree and send jobs to work. + g.Go(func() error { + defer close(work) - file, err := os.Open(target) - if err != nil { - return err - } - - offset := int64(0) - for _, blobID := range node.Content { - length, _ := res.repo.LookupBlobSize(blobID, restic.DataBlob) - buf = buf[:length] - _, err = file.ReadAt(buf, offset) - if err != nil { - _ = file.Close() - return err + _, err := res.traverseTree(ctx, dst, string(filepath.Separator), *res.sn.Tree, treeVisitor{ + enterDir: func(node *restic.Node, target, location string) error { return nil }, + visitNode: func(node *restic.Node, target, location string) error { + if node.Type != "file" { + return nil } - if !blobID.Equal(restic.Hash(buf)) { - _ = file.Close() - return errors.Errorf("Unexpected contents starting at offset %d", offset) + select { + case <-ctx.Done(): + return ctx.Err() + case work <- mustCheck{node, target}: + return nil } - offset += int64(length) - } - - return file.Close() - }, - leaveDir: func(node *restic.Node, target, location string) error { return nil }, + }, + leaveDir: func(node *restic.Node, target, location string) error { return nil }, + }) + return err }) - return count, err + for i := 0; i < nVerifyWorkers; i++ { + g.Go(func() (err error) { + var buf []byte + for job := range work { + atomic.AddUint64(&nchecked, 1) + buf, err = res.verifyFile(job.path, job.node, buf) + if err != nil { + break + } + } + return + }) + } + + return int(nchecked), g.Wait() +} + +// Verify that the file target has the contents of node. +// buf and the first return value are scratch space, passed around for reuse. +func (res *Restorer) verifyFile(target string, node *restic.Node, buf []byte) ([]byte, error) { + f, err := os.Open(target) + if err != nil { + return buf, err + } + defer f.Close() + + fi, err := f.Stat() + switch { + case err != nil: + return nil, err + case int64(node.Size) != fi.Size(): + return buf, errors.Errorf("Invalid file size for %s: expected %d, got %d", + target, node.Size, fi.Size()) + } + + var offset int64 + for _, blobID := range node.Content { + length, found := res.repo.LookupBlobSize(blobID, restic.DataBlob) + if !found { + return buf, errors.Errorf("Unable to fetch blob %s", blobID) + } + + if length > uint(cap(buf)) { + newcap := uint(2 * cap(buf)) + if newcap < length { + newcap = length + } + buf = make([]byte, newcap) + } + buf = buf[:length] + + _, err = f.ReadAt(buf, offset) + if err != nil { + return buf, err + } + if !blobID.Equal(restic.Hash(buf)) { + return buf, errors.Errorf( + "Unexpected content in %s, starting at offset %d", + target, offset) + } + offset += int64(length) + } + + return buf, nil } From de8521ae567d937f8f747c265c78ad533b0859a6 Mon Sep 17 00:00:00 2001 From: greatroar <@> Date: Fri, 21 Feb 2020 09:51:43 +0100 Subject: [PATCH 05/12] Report number of successes from Restorer.VerifyFiles Previously, the number of attempts was reported. --- internal/restorer/restorer.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/internal/restorer/restorer.go b/internal/restorer/restorer.go index 60f9dc022..0d6e29b6d 100644 --- a/internal/restorer/restorer.go +++ b/internal/restorer/restorer.go @@ -317,8 +317,8 @@ const nVerifyWorkers = 8 // VerifyFiles checks whether all regular files in the snapshot res.sn // have been successfully written to dst. It stops when it encounters an -// error. It returns that error and the number of files it has checked, -// including the file(s) that caused errors. +// error. It returns that error and the number of files it has successfully +// verified. func (res *Restorer) VerifyFiles(ctx context.Context, dst string) (int, error) { type mustCheck struct { node *restic.Node @@ -358,11 +358,11 @@ func (res *Restorer) VerifyFiles(ctx context.Context, dst string) (int, error) { g.Go(func() (err error) { var buf []byte for job := range work { - atomic.AddUint64(&nchecked, 1) buf, err = res.verifyFile(job.path, job.node, buf) if err != nil { break } + atomic.AddUint64(&nchecked, 1) } return }) From d4225ec8031fbb65f138eb420c78a9e893aed86b Mon Sep 17 00:00:00 2001 From: greatroar <@> Date: Mon, 16 Mar 2020 10:24:24 +0100 Subject: [PATCH 06/12] Simplify buffer growing in Restorer.verifyFile Suggested-by: Igor Fedorenko --- internal/restorer/restorer.go | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/internal/restorer/restorer.go b/internal/restorer/restorer.go index 0d6e29b6d..7ce7bb04a 100644 --- a/internal/restorer/restorer.go +++ b/internal/restorer/restorer.go @@ -397,11 +397,7 @@ func (res *Restorer) verifyFile(target string, node *restic.Node, buf []byte) ([ } if length > uint(cap(buf)) { - newcap := uint(2 * cap(buf)) - if newcap < length { - newcap = length - } - buf = make([]byte, newcap) + buf = make([]byte, 2*length) } buf = buf[:length] From d35774410422c9a93ddf20cc60e4a8259b391e94 Mon Sep 17 00:00:00 2001 From: greatroar <@> Date: Mon, 16 Mar 2020 10:05:59 +0100 Subject: [PATCH 07/12] Handle canceled context in restore --verify properly --- internal/restorer/restorer.go | 11 +++++---- internal/restorer/restorer_test.go | 38 ++++++++++++++++++++++++++++++ 2 files changed, 45 insertions(+), 4 deletions(-) diff --git a/internal/restorer/restorer.go b/internal/restorer/restorer.go index 7ce7bb04a..5b6604421 100644 --- a/internal/restorer/restorer.go +++ b/internal/restorer/restorer.go @@ -99,10 +99,13 @@ func (res *Restorer) traverseTree(ctx context.Context, target, location string, } sanitizeError := func(err error) error { - if err != nil { - err = res.Error(nodeLocation, err) + switch err { + case nil, context.Canceled, context.DeadlineExceeded: + // Context errors are permanent. + return err + default: + return res.Error(nodeLocation, err) } - return err } if node.Type == "dir" { @@ -364,7 +367,7 @@ func (res *Restorer) VerifyFiles(ctx context.Context, dst string) (int, error) { } atomic.AddUint64(&nchecked, 1) } - return + return err }) } diff --git a/internal/restorer/restorer_test.go b/internal/restorer/restorer_test.go index 4a51c2c19..4c4093464 100644 --- a/internal/restorer/restorer_test.go +++ b/internal/restorer/restorer_test.go @@ -808,3 +808,41 @@ func TestRestorerConsistentTimestampsAndPermissions(t *testing.T) { checkConsistentInfo(t, test.path, f, test.modtime, test.mode) } } + +// VerifyFiles must not report cancelation of its context through res.Error. +func TestVerifyCancel(t *testing.T) { + snapshot := Snapshot{ + Nodes: map[string]Node{ + "foo": File{Data: "content: foo\n"}, + }, + } + + repo, cleanup := repository.TestRepository(t) + defer cleanup() + + _, id := saveSnapshot(t, repo, snapshot) + + res, err := NewRestorer(context.TODO(), repo, id) + rtest.OK(t, err) + + tempdir, cleanup := rtest.TempDir(t) + defer cleanup() + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + rtest.OK(t, res.RestoreTo(ctx, tempdir)) + err = ioutil.WriteFile(filepath.Join(tempdir, "foo"), []byte("bar"), 0644) + rtest.OK(t, err) + + var errs []error + res.Error = func(filename string, err error) error { + errs = append(errs, err) + return err + } + + nverified, err := res.VerifyFiles(ctx, tempdir) + rtest.Equals(t, 0, nverified) + rtest.Assert(t, err != nil, "nil error from VerifyFiles") + rtest.Equals(t, []error(nil), errs) +} From 2b94742ca533345c7717a4ea6c677f02b479d5c4 Mon Sep 17 00:00:00 2001 From: greatroar <@> Date: Mon, 16 Mar 2020 15:20:00 +0100 Subject: [PATCH 08/12] Replace no-op closures in restorer by nil check --- internal/restorer/restorer.go | 18 +++--------------- 1 file changed, 3 insertions(+), 15 deletions(-) diff --git a/internal/restorer/restorer.go b/internal/restorer/restorer.go index 5b6604421..b13bc4d24 100644 --- a/internal/restorer/restorer.go +++ b/internal/restorer/restorer.go @@ -113,7 +113,7 @@ func (res *Restorer) traverseTree(ctx context.Context, target, location string, return hasRestored, errors.Errorf("Dir without subtree in tree %v", treeID.Str()) } - if selectedForRestore { + if selectedForRestore && visitor.enterDir != nil { err = sanitizeError(visitor.enterDir(node, nodeTarget, nodeLocation)) if err != nil { return hasRestored, err @@ -138,7 +138,7 @@ func (res *Restorer) traverseTree(ctx context.Context, target, location string, // metadata need to be restore when leaving the directory in both cases // selected for restore or any child of any subtree have been restored - if selectedForRestore || childHasRestored { + if (selectedForRestore || childHasRestored) && visitor.leaveDir != nil { err = sanitizeError(visitor.leaveDir(node, nodeTarget, nodeLocation)) if err != nil { return hasRestored, err @@ -219,7 +219,6 @@ func (res *Restorer) RestoreTo(ctx context.Context, dst string) error { } idx := restic.NewHardlinkIndex() - filerestorer := newFileRestorer(dst, res.repo.Backend().Load, res.repo.Key(), res.repo.Index().Lookup) filerestorer.Error = res.Error @@ -262,9 +261,6 @@ func (res *Restorer) RestoreTo(ctx context.Context, dst string) error { return nil }, - leaveDir: func(node *restic.Node, target, location string) error { - return nil - }, }) if err != nil { return err @@ -279,9 +275,6 @@ func (res *Restorer) RestoreTo(ctx context.Context, dst string) error { // second tree pass: restore special files and filesystem metadata _, err = res.traverseTree(ctx, dst, string(filepath.Separator), *res.sn.Tree, treeVisitor{ - enterDir: func(node *restic.Node, target, location string) error { - return nil - }, visitNode: func(node *restic.Node, target, location string) error { debug.Log("second pass, visitNode: restore node %q", location) if node.Type != "file" { @@ -302,10 +295,7 @@ func (res *Restorer) RestoreTo(ctx context.Context, dst string) error { return res.restoreNodeMetadataTo(node, target, location) }, - leaveDir: func(node *restic.Node, target, location string) error { - debug.Log("second pass, leaveDir restore metadata %q", location) - return res.restoreNodeMetadataTo(node, target, location) - }, + leaveDir: res.restoreNodeMetadataTo, }) return err } @@ -340,7 +330,6 @@ func (res *Restorer) VerifyFiles(ctx context.Context, dst string) (int, error) { defer close(work) _, err := res.traverseTree(ctx, dst, string(filepath.Separator), *res.sn.Tree, treeVisitor{ - enterDir: func(node *restic.Node, target, location string) error { return nil }, visitNode: func(node *restic.Node, target, location string) error { if node.Type != "file" { return nil @@ -352,7 +341,6 @@ func (res *Restorer) VerifyFiles(ctx context.Context, dst string) (int, error) { return nil } }, - leaveDir: func(node *restic.Node, target, location string) error { return nil }, }) return err }) From bdcdfaf6b431496ae8721c0e9091c4a5a8696d70 Mon Sep 17 00:00:00 2001 From: greatroar <@> Date: Thu, 19 Mar 2020 12:56:11 +0100 Subject: [PATCH 09/12] restore --verify: buffer reuse consistency and comment --- internal/restorer/restorer.go | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/internal/restorer/restorer.go b/internal/restorer/restorer.go index b13bc4d24..13248eec2 100644 --- a/internal/restorer/restorer.go +++ b/internal/restorer/restorer.go @@ -363,7 +363,10 @@ func (res *Restorer) VerifyFiles(ctx context.Context, dst string) (int, error) { } // Verify that the file target has the contents of node. +// // buf and the first return value are scratch space, passed around for reuse. +// Reusing buffers prevents the verifier goroutines allocating all of RAM and +// flushing the filesystem cache (at least on Linux). func (res *Restorer) verifyFile(target string, node *restic.Node, buf []byte) ([]byte, error) { f, err := os.Open(target) if err != nil { @@ -374,7 +377,7 @@ func (res *Restorer) verifyFile(target string, node *restic.Node, buf []byte) ([ fi, err := f.Stat() switch { case err != nil: - return nil, err + return buf, err case int64(node.Size) != fi.Size(): return buf, errors.Errorf("Invalid file size for %s: expected %d, got %d", target, node.Size, fi.Size()) From 2cdc0719af6f42e7ece97d79edafef4992cafa7f Mon Sep 17 00:00:00 2001 From: Michael Eischer Date: Sun, 19 Sep 2021 13:21:57 +0200 Subject: [PATCH 10/12] restorer: Sanitize verify errors --- internal/restorer/restorer.go | 3 +++ internal/restorer/restorer_test.go | 3 ++- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/internal/restorer/restorer.go b/internal/restorer/restorer.go index 13248eec2..9f30ea00b 100644 --- a/internal/restorer/restorer.go +++ b/internal/restorer/restorer.go @@ -351,6 +351,9 @@ func (res *Restorer) VerifyFiles(ctx context.Context, dst string) (int, error) { for job := range work { buf, err = res.verifyFile(job.path, job.node, buf) if err != nil { + err = res.Error(job.path, err) + } + if err != nil || ctx.Err() != nil { break } atomic.AddUint64(&nchecked, 1) diff --git a/internal/restorer/restorer_test.go b/internal/restorer/restorer_test.go index 4c4093464..a5a3bb5ba 100644 --- a/internal/restorer/restorer_test.go +++ b/internal/restorer/restorer_test.go @@ -844,5 +844,6 @@ func TestVerifyCancel(t *testing.T) { nverified, err := res.VerifyFiles(ctx, tempdir) rtest.Equals(t, 0, nverified) rtest.Assert(t, err != nil, "nil error from VerifyFiles") - rtest.Equals(t, []error(nil), errs) + rtest.Equals(t, 1, len(errs)) + rtest.Assert(t, strings.Contains(errs[0].Error(), "Invalid file size for"), "wrong error %q", errs[0].Error()) } From e62d4f622f609279d56bbc437a6537fc616cbd5b Mon Sep 17 00:00:00 2001 From: Michael Eischer Date: Sun, 19 Sep 2021 14:07:56 +0200 Subject: [PATCH 11/12] Reword changelog --- changelog/unreleased/pull-2594 | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/changelog/unreleased/pull-2594 b/changelog/unreleased/pull-2594 index 516dc50da..76d22202f 100644 --- a/changelog/unreleased/pull-2594 +++ b/changelog/unreleased/pull-2594 @@ -1,7 +1,6 @@ Enhancement: Speed up restic restore --verify -The --verify option causes restic restore to do some verification after it -has restored from a snapshot. This verification now runs up to 52% faster, -depending on the exact setup. +The --verify option lets restic restore verify the file content after it has +restored a snapshot. We've sped up the verification by up to a factor of two. https://github.com/restic/restic/pull/2594 From 921e328b56eaf49aa17a9cf97ecc7a011e1f2160 Mon Sep 17 00:00:00 2001 From: Michael Eischer Date: Sun, 19 Sep 2021 14:14:35 +0200 Subject: [PATCH 12/12] restore: Fix linting error --- internal/restorer/restorer.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/internal/restorer/restorer.go b/internal/restorer/restorer.go index 9f30ea00b..a1e5b3628 100644 --- a/internal/restorer/restorer.go +++ b/internal/restorer/restorer.go @@ -375,7 +375,9 @@ func (res *Restorer) verifyFile(target string, node *restic.Node, buf []byte) ([ if err != nil { return buf, err } - defer f.Close() + defer func() { + _ = f.Close() + }() fi, err := f.Stat() switch {