refactor(general): Increase restore progress granularity #3655

e-sumin · 2024-02-18T17:52:42Z

When restoring huge file(s), the progress reporting is done in a bit weird way:

kopia_test % kopia snapshot restore ka2084d263182164b6cf3456668e6b6da /Users/eugen.sumin/kopia_test/2
Restoring to local filesystem (/Users/eugen.sumin/kopia_test/2) with parallelism=8...
Processed 6 (5.4 GB) of 5 (5.4 GB) 1.6 MB/s (100.0%) remaining 0s.
Processed 6 (5.4 GB) of 5 (5.4 GB) 1.6 MB/s (100.0%) remaining 0s.
Processed 6 (5.4 GB) of 5 (5.4 GB) 1.6 MB/s (100.0%) remaining 0s.
Processed 6 (5.4 GB) of 5 (5.4 GB) 1.5 MB/s (100.0%) remaining 0s.
Processed 6 (5.4 GB) of 5 (5.4 GB) 1.5 MB/s (100.0%) remaining 0s.
Processed 6 (5.4 GB) of 5 (5.4 GB) 1.5 MB/s (100.0%) remaining 0s.
Restored 5 files, 1 directories and 0 symbolic links (5.4 GB).

In fact, the amount of restored data is dumped when particular file completely restored.

This PR contains the least invasive change, which allows us to see progress update while file is downloaded from object storage.

Restoring to local filesystem (/Users/eugen.sumin/kopia_test/55) with parallelism=8...
Processed 2 (3.1 MB) of 5 (1.8 GB).
Processed 4 (459.6 MB) of 5 (1.8 GB) 270.3 MB/s (25.2%) remaining 4s.
Processed 4 (468.7 MB) of 5 (1.8 GB) 269 MB/s (25.7%) remaining 4s.
Processed 4 (741.6 MB) of 5 (1.8 GB) 269 MB/s (40.6%) remaining 3s.
Processed 4 (1.1 GB) of 5 (1.8 GB) 280 MB/s (57.6%) remaining 2s.
Processed 5 (1.4 GB) of 5 (1.8 GB) 291.1 MB/s (75.2%) remaining 1s.
Processed 5 (1.4 GB) of 5 (1.8 GB) 289.8 MB/s (75.6%) remaining 1s.
Processed 5 (1.6 GB) of 5 (1.8 GB) 270.2 MB/s (85.3%) remaining 0s.
Processed 5 (1.7 GB) of 5 (1.8 GB) 256.3 MB/s (95.0%) remaining 0s.
Processed 6 (1.8 GB) of 5 (1.8 GB) 251 MB/s (100.0%) remaining 0s.
Processed 6 (1.8 GB) of 5 (1.8 GB) 251 MB/s (100.0%) remaining 0s.
Restored 5 files, 1 directories and 0 symbolic links (1.8 GB).

e-sumin · 2024-02-18T17:53:39Z

@KastenMike @julio-lopez could you please review ?

jkowalski · 2024-02-19T03:32:57Z

repo/object/object_reader.go


+// FileReadingProgressCallback is a callback intended to be used during file copying
+// to report amount of data sent to destination.
+type FileReadingProgressCallback func(chunkSize int64)


why do we need to change object reader at all, can't we just emit the progress as we're reading the bytes during restore?

this does not seem used anywhere, the rest looks good

codecov · 2024-02-19T03:34:22Z

Codecov Report

Attention: Patch coverage is 83.20000% with 21 lines in your changes are missing coverage. Please review.

Project coverage is 77.18%. Comparing base (cb455c6) to head (3b49d9a).
Report is 133 commits behind head on master.

Files	Patch %	Lines
cli/cli_progress.go	77.58%	8 Missing and 5 partials ⚠️
snapshot/restore/local_fs_output.go	63.15%	7 Missing ⚠️
snapshot/restore/restore.go	95.23%	0 Missing and 1 partial ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #3655      +/-   ##
==========================================
+ Coverage   75.86%   77.18%   +1.31%     
==========================================
  Files         470      479       +9     
  Lines       37301    28756    -8545     
==========================================
- Hits        28299    22194    -6105     
+ Misses       7071     4660    -2411     
+ Partials     1931     1902      -29

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

jkowalski · 2024-02-19T03:38:37Z

snapshot/restore/local_fs_output.go

 	}
 	defer r.Close() //nolint:errcheck

+	type withProgressTracking interface {


I think it's easier to wrap "r" so that it reports bytes written in the callback.

Thank you for the idea, I've changed the code, is it what you meant ?

e-sumin · 2024-03-04T11:03:26Z

@jkowalski do you think the changes could be merged ? Or something else has to be done before ?

e-sumin · 2024-03-11T15:51:56Z

@jkowalski do you think the changes could be merged ? Or something else has to be done before ?

Don't want to be annoying, just a friendly reminder :)

denisvmedia · 2024-03-28T09:36:34Z

@jkowalski @redgoat650 @julio-lopez could you please check this PR?

Shrekster · 2024-04-03T17:32:05Z

snapshot/restore/local_fs_output.go

 	}

-	return write(targetPath, r, f.Size(), o.copier)
+	return write(targetPath, wr, f.Size(), o.copier)


@e-sumin Question about the progress reporting using the reader tracking mechanism:

What is the best way to evaluate progress, as in the definition of done on processing X bytes ? When we have read X bytes from the reader does that mean we are done writing X bytes to the target ? In other words, would it be possible to get in a scenario where we have read 100% of the data from repository and are still stuck writing the final block due to a network issue (NFS) or similar ?

That's true, but this way of progress update was chosen because it is less intrusive. Also, when reading, usually, the block is very small in comparison with total amount of data. So, we, anyway, can get 100% earlier than last block will be read. So, I'd not consider this as critical flaw.

Shrekster · 2024-04-03T17:42:21Z

snapshot/restore/restore.go

+		bytesWritten := int64(0)
+		progressCallback := func(chunkSize int64) {
+			bytesWritten += chunkSize
+			c.stats.RestoredTotalFileSize.Add(chunkSize)


nit; this callback is hit each time we have read chunkSize from the repository, not necessarily "bytes written". Is that correct ? This is w.r.t. to the my other comment as well.

Yes, that's correct. This progress calculation way treats bytes read as bytes written.

Shrekster · 2024-04-04T20:42:39Z

@e-sumin and I discussed this over a call and he explained why the reader based approach is correct / simpler for now. I also agree with his comments above.

@e-sumin is looking into adding unit-test coverage with a custom test-only callback plumbing to make it non-flaky.

Wrapping is not needed while we are just proxifying requests.

e-sumin · 2024-05-06T10:08:10Z

I did some refactoring of snapshot restore:

progress reporting interval is taken from command line, as it was done for upload progress reporting
- currently upload progress instance is keeping progress flag and interval and restore progress just utilizes its value (this was originally discussed with @Shrekster as less invasive thing)
- cli progress refactoring should be done (but probably it would be better to have it as a separate PR). We need to extract flag and interval and throttling mechanism to reused part and create progress instance depending on operation (upload or restore)
  - this also will allow to write separate tests for progress reporting format and progress reporting intervals
probably it would be better to pass restore progress interface to copier and increase counters separately when needed instead of keeping another copy of stats in copier and passing its values to progress reporter.

Some of changes I've done was done to be able to have an unit test which verifies that progress is reported properly.

…ogress_granularity

e-sumin · 2024-05-09T20:28:41Z

I've fixed the test and merged master into my branch. The tests should pass now.

tests/end_to_end_test/restore_test.go

snapshot/restore/local_fs_output.go

denisvmedia · 2024-05-13T10:02:19Z

snapshot/restore/restore_progress.go

+
+// Progress is invoked by copier to report status of snapshot restoration.
+type Progress interface {
+	SetCounters(


Too late to comment here, but I believe having an args struct would be better.

@denisvmedia In the context of how this function is called, it does make sense to use a struct as an argument, more specifically restore.Stats. That would allow simply passing the struct as is, and would make the call just slightly simpler.

However, this pattern of using a struct to pass a bunch of arguments should be avoided in general, as it essentially makes all the arguments "optional". This becomes error prone as it makes it easy to miss setting a value and simply passing 0 (the default value).

julio-lopez

@e-sumin see couple of minor comments

snapshot/restore/local_fs_output.go

julio-lopez · 2024-08-14T04:46:48Z

snapshot/restore/restore_progress.go

+
+// Progress is invoked by copier to report status of snapshot restoration.
+type Progress interface {
+	SetCounters(


@denisvmedia In the context of how this function is called, it does make sense to use a struct as an argument, more specifically restore.Stats. That would allow simply passing the struct as is, and would make the call just slightly simpler.

However, this pattern of using a struct to pass a bunch of arguments should be avoided in general, as it essentially makes all the arguments "optional". This becomes error prone as it makes it easy to miss setting a value and simply passing 0 (the default value).

Followups to #3655 * wrap fs.Reader * nit: remove unnecessary intermediate variable * nit: rename local variable * cleanup: move restore.Progress interface to cli pkg * move cliRestoreProgress to a separate file * refactor(general): replace switch with if/else for clarity Removes a tautology for `err == nil`, which was guaranteed to be true in the second case statement for the switch. Replacing the switch statement with and if/else block is clearer. * initialize restoreProgress in restore command * fix: use error.Wrapf with format string and args Simplify SetCounters signature: Pass arguments in a `restore.Stats` struct. `SetCounters(s restore.Stats)` Simplifies call sites and implementation. In this case it makes sense to pass all the values using the restore.Stats struct as it simplifies the calls. However, this pattern should be avoided in general as it essentially makes all the arguments "optional". This makes it easy to miss setting a value and simply passing 0 (the default value), thus it becomes error prone. In this particular case, the struct is being passed through verbatim, thus eliminating the risk of missing a value, at least in the current state of the code.

When restoring huge file(s), the progress reporting is done in a bit weird way: ``` kopia_test % kopia snapshot restore ka2084d263182164b6cf3456668e6b6da /Users/eugen.sumin/kopia_test/2 Restoring to local filesystem (/Users/eugen.sumin/kopia_test/2) with parallelism=8... Processed 6 (5.4 GB) of 5 (5.4 GB) 1.6 MB/s (100.0%) remaining 0s. Processed 6 (5.4 GB) of 5 (5.4 GB) 1.6 MB/s (100.0%) remaining 0s. Processed 6 (5.4 GB) of 5 (5.4 GB) 1.6 MB/s (100.0%) remaining 0s. Processed 6 (5.4 GB) of 5 (5.4 GB) 1.5 MB/s (100.0%) remaining 0s. Processed 6 (5.4 GB) of 5 (5.4 GB) 1.5 MB/s (100.0%) remaining 0s. Processed 6 (5.4 GB) of 5 (5.4 GB) 1.5 MB/s (100.0%) remaining 0s. Restored 5 files, 1 directories and 0 symbolic links (5.4 GB). ``` In fact, the amount of restored data is dumped when particular file completely restored. This PR contains the least invasive change, which allows us to see progress update while file is downloaded from object storage. ``` Restoring to local filesystem (/Users/eugen.sumin/kopia_test/55) with parallelism=8... Processed 2 (3.1 MB) of 5 (1.8 GB). Processed 4 (459.6 MB) of 5 (1.8 GB) 270.3 MB/s (25.2%) remaining 4s. Processed 4 (468.7 MB) of 5 (1.8 GB) 269 MB/s (25.7%) remaining 4s. Processed 4 (741.6 MB) of 5 (1.8 GB) 269 MB/s (40.6%) remaining 3s. Processed 4 (1.1 GB) of 5 (1.8 GB) 280 MB/s (57.6%) remaining 2s. Processed 5 (1.4 GB) of 5 (1.8 GB) 291.1 MB/s (75.2%) remaining 1s. Processed 5 (1.4 GB) of 5 (1.8 GB) 289.8 MB/s (75.6%) remaining 1s. Processed 5 (1.6 GB) of 5 (1.8 GB) 270.2 MB/s (85.3%) remaining 0s. Processed 5 (1.7 GB) of 5 (1.8 GB) 256.3 MB/s (95.0%) remaining 0s. Processed 6 (1.8 GB) of 5 (1.8 GB) 251 MB/s (100.0%) remaining 0s. Processed 6 (1.8 GB) of 5 (1.8 GB) 251 MB/s (100.0%) remaining 0s. Restored 5 files, 1 directories and 0 symbolic links (1.8 GB). ``` --------- Co-authored-by: Shikhar Mall <mall.shikhar.in@gmail.com>

Followups to kopia#3655 * wrap fs.Reader * nit: remove unnecessary intermediate variable * nit: rename local variable * cleanup: move restore.Progress interface to cli pkg * move cliRestoreProgress to a separate file * refactor(general): replace switch with if/else for clarity Removes a tautology for `err == nil`, which was guaranteed to be true in the second case statement for the switch. Replacing the switch statement with and if/else block is clearer. * initialize restoreProgress in restore command * fix: use error.Wrapf with format string and args Simplify SetCounters signature: Pass arguments in a `restore.Stats` struct. `SetCounters(s restore.Stats)` Simplifies call sites and implementation. In this case it makes sense to pass all the values using the restore.Stats struct as it simplifies the calls. However, this pattern should be avoided in general as it essentially makes all the arguments "optional". This makes it easy to miss setting a value and simply passing 0 (the default value), thus it becomes error prone. In this particular case, the struct is being passed through verbatim, thus eliminating the risk of missing a value, at least in the current state of the code.

e-sumin added 2 commits February 13, 2024 12:41

When downloading file from repo, report amount of downloaded bytes

fb76560

Remove redundant counter and add comment

8e63f7e

jkowalski reviewed Feb 19, 2024

View reviewed changes

e-sumin added 3 commits February 26, 2024 22:23

Capture amount of data using wrapper for fs.Reader

ff440e6

Fix crash

5c4e957

Remove redundant callback

ce7bf79

Shrekster reviewed Apr 3, 2024

View reviewed changes

e-sumin added 4 commits May 2, 2024 11:19

Fix issues highlighted by linter.

cd6c798

Wrapping is not needed while we are just proxifying requests.

Refactor restore progress reporting using CLI parameters

e112f4d

Introduce RestoreProgress interface

acd690e

Add restore progress test

88604c3

e-sumin requested a review from Shrekster May 6, 2024 10:08

e-sumin added 2 commits May 9, 2024 22:27

Fix race in tests

a10a3cb

Merge remote-tracking branch 'origin/master' into increase_restore_pr…

a8171ee

…ogress_granularity

Shrekster reviewed May 9, 2024

View reviewed changes

tests/end_to_end_test/restore_test.go Outdated Show resolved Hide resolved

Update tests/end_to_end_test/restore_test.go

0f9140d

Shrekster reviewed May 9, 2024

View reviewed changes

snapshot/restore/local_fs_output.go Show resolved Hide resolved

Update snapshot/restore/local_fs_output.go

3b49d9a

Shrekster approved these changes May 10, 2024

View reviewed changes

Shrekster merged commit 2b92388 into kopia:master May 10, 2024

denisvmedia reviewed May 13, 2024

View reviewed changes

julio-lopez mentioned this pull request Jul 28, 2024

refactor(general): minor cleanups #4003

Merged

julio-lopez reviewed Aug 14, 2024

View reviewed changes

This was referenced Aug 28, 2024

Bump up kopia for 1.15 vmware-tanzu/velero#8155

Closed

fix(general): upstream bump up for 1.15 project-velero/kopia#18

Merged

refactor(general): Increase restore progress granularity #3655

refactor(general): Increase restore progress granularity #3655

Uh oh!

Conversation

e-sumin commented Feb 18, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

e-sumin commented Feb 18, 2024

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

codecov bot commented Feb 19, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

e-sumin commented Mar 4, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

e-sumin commented Mar 11, 2024

Uh oh!

denisvmedia commented Mar 28, 2024

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Shrekster Apr 3, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Shrekster commented Apr 4, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

e-sumin commented May 6, 2024

Uh oh!

e-sumin commented May 9, 2024

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

julio-lopez left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

e-sumin commented Feb 18, 2024 •

edited

Loading

codecov bot commented Feb 19, 2024 •

edited

Loading

e-sumin commented Mar 4, 2024 •

edited

Loading

Shrekster Apr 3, 2024 •

edited

Loading

Shrekster commented Apr 4, 2024 •

edited

Loading