Hey @fd0,

I've implemented your suggestion. For the most part, the performance didn't change. However, I did notice with your suggestion that the debug logging doubled the time taken and dramatically increased the allocations, even when disabled. I tracked it down the the ID.Str() function, which allocates a string on call even if not used.

I made a second version that delays the calculation until used, for use with debug printing. I replaced the version used in Lookup, which helped the micro benchmark. I didn't see it show up in the backup profiling, so I'm not sure how much you want to take that change.

I originally tried replacing Str with DebugStr, but it broke various for loops in the frontend. If you wish, I can go back to that design and audit/test all those loops. But I'm not sure the performance advantage will beat out the risk of breakage (though it should be relatively visible). Alternately, I could just put those statements in a if statement, and have that be used only when the binary is compiled for debugging. Let me know what you prefer.

I also tried that script to check formatting, but it appears to not work well with my git habits. Thanks for pointing it out though!

Codecov Report

Merging #1549 into master will decrease coverage by 5.25%.
The diff coverage is 48.07%.

@@            Coverage Diff            @@
##           master   #1549      +/-   ##
=========================================
- Coverage   51.55%   46.3%   -5.26%     
=========================================
  Files         138     138              
  Lines       11081   11085       +4     
=========================================
- Hits         5713    5133     -580     
- Misses       4503    5141     +638     
+ Partials      865     811      -54

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 02f4f5d...27bfdb4. Read the comment docs.

However, I did notice with your suggestion that the debug logging doubled the time taken and dramatically increased the allocations, even when disabled. I tracked it down the the ID.Str() function, which allocates a string on call even if not used.

Hm, is that behavior new with the changes you made? That shouldn't be the case in my opinion, it probably was already present before.

Is it also there when compiled without the debug tag? If it isn't I don't really care, as the debug logs will also cost performance in other places. If it is also present without the debug tag, then remove the debug messages and move them up the call stack to some higher function (or just remove them, we'll add them back if needed).

Ugh, my sleepy brain wasn't clear with what was happening. So the changes in this PR (with or without the Id.DebugStr change) are faster then the previous version. However, when I changed the Lookup function to return a boolean, that caused the benchmarks to slow down slightly (but still generally faster then the previous version). The difference was that Index.Lookup has logging, which slowed down the not found case compared to the Has function which has no logging. Also this is all without the debug tag, so the rest of the logging is disabled.

I'll work to remove those log calls, but insert a few statements in some useful cases up the call stack. I just want to avoid these calls in the usual case, as you still pay the price.

Just to be clear, the reason this is an issue is that when Str() is called, there is some cpu time/memory allocations to return the string immediately. This happens regardless of whether or not the logging framework is enabled or does anything. I think currently that overhead is small enough to generally ignore, but in a very hot path there is some measurable overhead. I brought it up here since it showed up in my profiling.

However, when I changed the Lookup function to return a boolean, that caused the benchmarks to slow down slightly (but still generally faster then the previous version).

Thanks for the explanation. Can you show me the benchmarks?

I've thrown together a quick benchmark for debug.Log():

$ go test -v -bench . -benchmem
goos: linux
goarch: amd64
pkg: github.com/restic/restic/internal/debug
BenchmarkLogStatic-4     	2000000000	         1.77 ns/op	       0 B/op	       0 allocs/op
BenchmarkLogIDString-4   	300000000	         5.58 ns/op	       0 B/op	       0 allocs/op
BenchmarkLogIDStr-4      	100000000	        12.5 ns/op	       0 B/op	       0 allocs/op
PASS
ok  	github.com/restic/restic/internal/debug	7.242s

$ go test -v -tags debug -bench . -benchmem

debug enabled
goos: linux
goarch: amd64
pkg: github.com/restic/restic/internal/debug
BenchmarkLogStatic-4     	  200000	      8567 ns/op	     456 B/op	      20 allocs/op
BenchmarkLogIDString-4   	  200000	      8626 ns/op	     504 B/op	      21 allocs/op
BenchmarkLogIDStr-4      	  200000	      8644 ns/op	     488 B/op	      21 allocs/op
PASS
ok  	github.com/restic/restic/internal/debug	5.441s

We can see that the debug logging costs something, but there aren't any allocations when the debug tag isn't set. And since it's just a few nanoseconds (without debug) I wonder if it's worth optimizing further.

I've also tried changing debug.Log() to use reflection to call Str() if it is available (so it's really only executed when debug is active), then the cost of the debug.Log() call is about 6ns instead of 13ns for non-debug calls.

If you find good places up the call stack that's fine, otherwise just throw the calls to debug.Log() away for now.

Thanks for the explanation. Can you show me the benchmarks?
I added a commit containing some benchmarks. The results I get are noted below, and match about what I expect considering the speeds I got with my commits dealing with the ID.Str. I'm not sure why you're benchmarks report no difference between the three, that seems really odd to me. I do see the allocations and time associated when calling with .Str, and see a huge difference when using the debug tag.

If you don't want these benchmarks to stay with the code, please feel free to just pop the commit off this branch and before merging.

$ go test -run xx -bench . -benchmem -v
goos: linux
goarch: amd64
pkg: github.com/restic/restic/internal/debug
BenchmarkLogStatic-6            1000000000               2.41 ns/op            0 B/op          0 allocs/op
BenchmarkLogIDStr-6             20000000                94.7 ns/op            16 B/op          2 allocs/op
BenchmarkLogIDString-6          10000000               219 ns/op             128 B/op          2 allocs/op
PASS
ok      github.com/restic/restic/internal/debug 7.089s
$ go test -run xx -bench . -benchmem -v -tags debug
debug enabled
goos: linux
goarch: amd64
pkg: github.com/restic/restic/internal/debug
BenchmarkLogStatic-6              100000             12826 ns/op             432 B/op         20 allocs/op
BenchmarkLogIDStr-6               100000             14069 ns/op             440 B/op         23 allocs/op
BenchmarkLogIDString-6            100000             14058 ns/op             552 B/op         23 allocs/op
PASS
ok      github.com/restic/restic/internal/debug 4.523s

I also took a quick look at places where .Lookup is called (just doing a quick manual check with grep). Any interesting calls seem to already have a Log call if needed, so I just removed the calls instead. I also removed the whole commit adding DebugStr from this PR.

Nah, leave the benchmarks in. Can you please fix the code, there seems to be something wrong when run on Travis? Maybe you need to rebase on the latest master branch?

Ah, in master, the errors package was removed from several files, especially in fuse/, but this code reintroduces it, so the merged commit does not compile.

I suggest rebasing on the master branch, and then running goimports -w on the files.

Code rebased and changelog updated! Hopefully that's it :)

Out of curiosity, do you see benchmark results similar to mine with my benchmark code? I'm just curious why you don't see the difference in yours.

FYI, Travis is currently broken and does not run our tests on Darwin, so it looks like the tests failed (but they did not).

Ah, I forgot to run the benchmark again, sorry. I'll try to do that later today (also curious).

Hm, I think I did something wrong in my benchmarks (I don't have them any more), I'm seeing the same results as you did.

I've opened #1582 which removes all manual calls of id.Str() in debug.Log() and calls it afterwards in Log() via reflection.