A git bisect would be very helpful.

Also, for reference the actual commit links for 2e9f081 and 80b8377.

Bisect to 07e738e

note that the ns/op difference is much more obvious when running with large GOMAXPROCS

/cc @mknyszek @aclements

also noticed that 9108ae7 made make([]byte, 512) slower as well. not sure whether it is a feature or a bug ;)

/home/lni/src/go/bin/go test -bench .
goos: linux
goarch: amd64
pkg: github.com/lni/goplayground/makebenchmark
BenchmarkMakeByteSliceInParalell512-40    	10000000	       241 ns/op
BenchmarkMakeByteSliceInParalell8-40      	500000000	         4.00 ns/op
PASS
ok  	github.com/lni/goplayground/makebenchmark	5.013s

/home/lni/src/go/bin/go version
go version devel +a2a2901 Tue Oct 2 20:35:19 2018 +0000 linux/amd64

/home/lni/src/go/bin/go test -bench .
goos: linux
goarch: amd64
pkg: github.com/lni/goplayground/makebenchmark
BenchmarkMakeByteSliceInParalell512-40    	 5000000	       308 ns/op
BenchmarkMakeByteSliceInParalell8-40      	300000000	         4.07 ns/op
PASS
ok  	github.com/lni/goplayground/makebenchmark	3.476s

/home/lni/src/go/bin/go version
go version devel +9108ae7 Tue Oct 2 20:35:20 2018 +0000 linux/amd64

Thank you @reusee for the bisect !

CC @martisch

There were also some changes to runtime.makeslice. Modifying the benchmark to do no allocation in runtime.mallocgc shows the expected speed-up between go1.11.1 and tip. So its likely the slowdown to originates in runtime.mallocgc or below.

var LenVar = 0

func BenchmarkMakeSliceCallInParalell(b *testing.B) {
	b.RunParallel(func(pb *testing.PB) {
		for pb.Next() {
			m := make([]byte, LenVar)
			if len(m) != LenVar {
				b.Errorf("unexpected len")
			}
		}
	})
}

name                       old time/op  new time/op  delta
MakeSliceCallInParalell-4  3.50ns ± 5%  3.24ns ±10%  -7.35%  (p=0.000 n=17+20)

running the existing runtime MakeSlice benchmarks go1.11.1 vs tip:

MakeSlice/Byte-4       16.7ns ± 1%  15.7ns ± 2%   -5.93%  (p=0.000 n=10+10)
MakeSlice/Int16-4      19.1ns ± 2%  18.4ns ± 1%   -3.51%  (p=0.000 n=10+10)
MakeSlice/Int-4        25.9ns ± 1%  26.3ns ± 1%   +1.54%  (p=0.000 n=10+9)
MakeSlice/Ptr-4        64.1ns ± 2%  66.0ns ± 1%   +3.04%  (p=0.000 n=9+9)
MakeSlice/Struct/24-4  36.4ns ± 2%  35.7ns ± 5%     ~     (p=0.085 n=10+10)
MakeSlice/Struct/32-4  43.5ns ± 2%  39.7ns ± 1%   -8.75%  (p=0.000 n=10+10)
MakeSlice/Struct/40-4  56.5ns ± 1%  45.5ns ± 1%  -19.47%  (p=0.000 n=10+9)

so the slow down may only happen for larger or parallel allocations.

only see a smaller slow down for 512byte and speedup for 8byte on my laptop 2-core/4-thread for go1.11.1 vs go tip. So it is likely easier detectable with higher thread counts:

go1.11.1 vs go tip:

name                          old time/op    new time/op    delta
MakeByteSliceInParalell512-4     101ns ± 4%     118ns ± 7%  +16.54%  (p=0.000 n=19+19)
MakeByteSliceInParalell8-4      11.0ns ±18%    10.4ns ±15%   -5.50%  (p=0.003 n=18+18)

go1.11.1 vs 2e9f081 (commit before 9108ae7):

name                          old time/op    new time/op    delta
MakeByteSliceInParalell512-4     101ns ± 4%      97ns ± 4%  -3.78%  (p=0.000 n=19+20)
MakeByteSliceInParalell8-4      11.0ns ±18%    11.5ns ±28%    ~     (p=0.394 n=18+19)

As reusee@ sleuthed out, it's probably my commit (07e738e). Thank you everyone for looking into this.

I took some time to dig in and understand exactly what was going on. This benchmark exercises the case where we're allocating size-segregated spans with object size 512, which we then free, and re-allocate from. At first, I thought that the regression might have been the result of span allocation having to traverse the treap, instead of walking over a fixed-size array. But, CPU profiling shows that it's more likely a result of freeing spans. Before my change, freeing these size-segregated spans was a very fast operation: indexing into an array followed by a linked list insertion at head. Now, one needs to traverse a treap, allocate a treap node out of a SLAB, and rebalance it. While all of these operations should be reasonably fast, it's definitely more work than what was being done before. I think the regression in performance we see as a result of a higher GOMAXPROCS arises out of the fact that the heap lock is held when a span is freed, and my change causes this benchmark to spend more time holding the heap lock.

So, for a microbenchmark like this which really hammers on the GC and the allocator, it makes sense to me why my change had such an impact. Running other benchmarks (such as the go1 benchmarks, or the garbage benchmark, whose numbers are in my change's commit message) the actual performance hit isn't quite so dramatic. I quickly ran github.com/dr2chase/bent (which runs a number of benchmarks from actual Go programs in the wild) with my change and without it and I haven't yet seen any significant change there either. However, I will run those benchmarks with more iterations and report back with actual numbers.

The motivation behind my change was that it really simplified a number of changes I just landed today for #14045. I'm erring on the side that it was worth it, as it seems as though in practice the performance impact of my change appears to be relatively small.

Here are the numbers I promised: https://perf.golang.org/search?q=upload:20181031.2

The "before" is e508a5f072 (my commit's parent) and the "after" is 07e738ec32 (my commit).

@mknyszek , thanks for the above benchmark results and the explanation on 07e738e

I had a quick look at those numbers, it seems that they were probably generated using small GOMAXPROCS value (8)?

Below is the throughput results (in million ops/sec) of my library, I tried 4 different go versions and report the results of three runs. Sadly the library is not open sourced yet so I fully understand that these numbers are probably not very convincing/useful - just another data point to demonstrate the problem I am facing.

84b96c2
6.18, 6.12, 6.14

07e738e
6.26, 6.21, 6.23

e508a5f
6.66, 6.46, 6.48

go 1.11.1
6.70, 6.57, 6.54

Given that freeing spans are now more expensive, I am trying to further reduce my allocations. It is not always easy as some of them are caused in code auto generated by 3rd party libraries, e.g. Colfer in my case. I just have the feeling that now users have to pay more attention to all allocations.

Yeah GOMAXPROCS was at 8, and that's a good point. I've re-run the benchmarks with GOMAXPROCS=32. https://perf.golang.org/search?q=upload:20181102.1 The performance does indeed degrade more than with 8, but not by that much.

Thanks for sharing some of your numbers, and for letting me know it's impacting your application/library directly. Would you be willing to share a GC trace for each of the 4 revisions? (GODEBUG=gctrace=1)

@mknyszek , thanks for the updated benchmark results. yes, I agree that the differences are not huge.

GC traces you mentioned are posted below. Please feel free to let me know if there is any other trace/stats that can help to analyze the issue.

84b96c2

07e738e

e508a5f

go 1.11.1

EDITED: to add the <details> sections for easier inspection and scrolling.

Change https://golang.org/cl/151537 mentions this issue: runtime: add iterator abstraction for mTreap

Change https://golang.org/cl/151538 mentions this issue: runtime: specialize mTreap for spans of size 1

@lni do you mind trying out this patch with your application/library? (https://go-review.googlesource.com/c/go/+/151538)

The original numbers are a little harder to reproduce now as it seems other runtime/compiler improvements are hiding the original performance regression a little bit, but in some preliminary benchmarking it looked like the change above helped with your original benchmark.

I still need to start some longer runs for better statistical significance so I'll update here with those soon.

@mknyszek , thanks for the patch!

I didn't tag my library used for those initial benchmarks, my bad. Using the latest version of my library and slightly different configurations, I tried it on the following 3 Go revisions. Results below are in million op/sec.

It seems to me that the patch improved its performance.

go1.11.2
8.85, 8.72, 8.78

3ed46a7 (the new patch)
8.70, 8.74, 8.78, 8.88, 8.78, 8.79

57c8eb9 (before the patch)
8.45, 8.81, 8.37, 8.49, 8.66, 8.78

Change https://golang.org/cl/156918 mentions this issue: runtime: make mTreap iterator bidirectional

@mknyszek / @lni / @aclements can this be closed now? The regression fix for the real world usage has been merged.

The issue seems to be understood well enough that the fix for the GC is correct and confirmed.

Also the effect of the regression was about GC and neither the compiler nor slice support of the runtime was causing it.

Yeah closing this probably makes sense at this point. @lni feel free to reopen if you're still seeing issues for Go 1.11 -> Go 1.12, or a new bug if you're seeing problems with Go 1.13.