Reduce memory usage

[fd0]

In #85 @rubenv reported huge memory usage, this should be tracked (and fixed) in this issue.

@rubenv Could you try again with the current master branch? Thanks a lot!

[rubenv]

I've repeated my experiment from #85. Tests below were done with version bda33e6.

To recap:

My test set: 80449 directories, 318949 files (71Gb)

Machine used:

  Model Identifier: MacBookPro11,3
  Processor Name:   Intel Core i7
  Processor Speed:  2,6 GHz
  Number of Processors: 1
  Total Number of Cores:    4
  L2 Cache (per Core):  256 KB
  L3 Cache: 6 MB
  Memory:   16 GB

Backup is on same-disk SSD.

First run

scan /Users/ruben/Projects/
[0:37] 80449 directories, 318949 files, 70.662 GiB
Done in 0:37
[15:54] 100.00%  75.839 MiB/s  70.662 GiB / 70.662 GiB  399398 / 399398 items  ETA 0:00
duration: 15:54, 75.85MiB/s
snapshot af4aa783 saved

Strangely, it appears to have become even more hungry:

In #85 this was 1.04 GB. Does seem to stay constant throughout the backup.

Right before exiting it jumps up a little higher:

Is there any way we can get better numbers from this? Can we do heap profiling in Go?

Looking at the numbers, things also seemed to have slowed down a bit. Mind you though: this is a single run and highly unscientific.

Second run

found parent snapshot af4aa7831b5394bfb37e453f9616edcd493be69fb515d0ab0511e049d393f159
scan /Users/ruben/Projects/
[0:34] 80451 directories, 318949 files, 70.662 GiB
Done in 0:34
load old snapshot
[2:31] 100.00%  9.902 KiB/s  1.460 MiB / 1.460 MiB  82933 / 78992 items  ETA 0:00
duration: 2:31, 0.01MiB/s
snapshot b8a8f6e6 saved

Any ideas how we could easily track this over time?

[fd0]

Thanks for the data, I expected something like this. Yesterday, I've changed the chunker implementation to use streams instead of buffers, but the complete tree is still held in memory. My plan is to change the internals to use a pipeline-style processing infrastructure, but this is not yet finished and to be done this week. Before that is possible, I need to upgrade several other internal components (notably encryption and backend) to use streams. We'll see how that goes. Building a pipeline to process a tree structure of dependend nodes concurrently is surprisingly hard...

Do you have a good idea for a test that tracks memory usage over time?

[fd0]

The talk "Taking Out the Trash" by @kisielk is interesting, especially the -m build flag and running benchmarks with -benchmem and using benchcmp afterwards.

[fd0]

I spent some time to implement a pipeline-based architecture for backup and switched several internal parts to use the new stream-based (io.Reader/Writer) infrastructure, the results look promising:

$ benchcmp /tmp/{before.txt,after.txt}
benchmark                       old ns/op       new ns/op       delta
BenchmarkArchiveDirectory-4     29575095003     29529252607     -0.16%

benchmark                       old allocs     new allocs     delta
BenchmarkArchiveDirectory-4     417433         547351         +31.12%

benchmark                       old bytes      new bytes      delta
BenchmarkArchiveDirectory-4     2606303208     1312562288     -49.64%

The files before.txt and after.txt were created as follows:

$ go test -c
$ ./restic.test -test.run x -test.bench Archiver -test.cpu 4 -test.benchdir ~/shared/work/web -test.benchmem | tee /tmp/before.txt

Where ~/shared/work/web is a rather small directory:

$ du -sh ~/shared/work/web 
1.6G    /home/fd0/shared/work/web

$ find ~/shared/work/web -type f | wc -l
1522

$ find ~/shared/work/web -type d | wc -l
550

I have just pushed some commits to master (master is 06ed5c1 at the moment), if you like, please have a look.

Unfortunately, incremental backups are broken at the moment, the infrastructure is not yet ready.

[fd0]

Just pushed several improvements, it'd be good to have feedback on this :)

The current RAM usage for my ~/shared directory is about 150MiB total:

$ xtime restic backup ~/shared
scan /home/fd0/shared
[0:18] 36694 directories, 139258 files, 15.875 GiB
Done in 0:18
[6:37] 100.00%  40.918 MiB/s  15.875 GiB / 15.875 GiB  0 / 175952 items  ETA 0:00
duration: 6:37, 40.95MiB/s
snapshot 395cc8e3 saved
1048.06u 84.69s 416.69r 153740kB restic backup /home/fd0/shared

And it's even faster, too! I usually got only ~30MiB/s until today...

btw: xtime is a nice little shell script taken from here (so you don't have to do screenshots all the time): https://blog.golang.org/profiling-go-programs

[fd0]

@rubenv Did you find time yet to give it a shot again?

[rubenv]

Yes I did!

It's gotten better. Here's the output:

$ restic -r /tmp/restic backup ~/Projects/
Enter Password for Repository: 
scan [/Users/ruben/Projects]
scanned 94008 directories, 368370 files in 0:31
loading blobs
[10:24] 100.00%  119.321 MiB/s  72.711 GiB / 72.711 GiB  464671 / 462378 items  ETA 0:00 
duration: 10:24, 119.32MiB/s
snapshot 4400f241 saved

As for the memory usage: it starts up at about 250mb (much much less than before). Then it slowly starts to climb:

Halfway in:

75% done:

When finished:

[rubenv]

Second backup of same data set seems to error though:

$ restic -r /tmp/restic backup ~/Projects/ 4400f241                                                                                                                                                                                                                                                                   
Enter Password for Repository: 
scan [/Users/ruben/Projects /Users/ruben/4400f241]
error for /Users/ruben/4400f241: lstat /Users/ruben/4400f241: no such file or directory
scanned 94008 directories, 368370 files in 0:30
loading blobs
[1:15] 0.00%  0B/s  0B / 72.711 GiB  0 / 462378 items  ETA 0:00 

At this point it just hangs (no activity). Note the stat error, there's probably something broken in there.

Had to kill it.

For completeness, the memory usage at this point:

Both runs were performed with git revision f51aba1

[rubenv]

Without the snapshot reference:

$ restic -r /tmp/restic backup ~/Projects/ 
Enter Password for Repository: 
scan [/Users/ruben/Projects]
scanned 94008 directories, 368370 files in 0:35
loading blobs
[6:27] 100.00%  192.394 MiB/s  72.711 GiB / 72.711 GiB  464671 / 462378 items  ETA 0:00 
duration: 6:27, 192.39MiB/s
snapshot 0bef4e82 saved

This backup barely introduced new data (which is why it's so fast), so I guess the memory bubbling is in the blob packing.

[fd0]

Thanks for trying it again. I must acknowledge that you found a bug: the second run with restic backup should've terminated. In addition, the syntax for doing an "incremental" backup has changed, the old snapshot must be specified in the -p parameter like this:

restic -r /tmp/restic backup -p 4400f241 ~/Projects/

Once #105 is done this should not be necessary any more.

[fd0]

The bug you found is fixed in b86786a, a test is added in 8eccfc6. Basically, when a non-existing file/directory is listed on the command line, restic waits endlessly for files from this dir (which does not exist).

[fd0]

I think this issue is closed for now.