runtime: frequent enlisting of short-lived background workers leads to performance regression with async preemption

[klauspost]

What version of Go are you using (go version)?

λ go version
go version go1.14 windows/amd64

λ go version
go version go1.13.8 windows/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

go env Output

λ go env                                                                                                                                       
set GO111MODULE=                                                                                                                               
set GOARCH=amd64                                                                                                                               
set GOBIN=                                                                                                                                     
set GOCACHE=C:\Users\klaus\AppData\Local\go-build                                                                                              
set GOENV=C:\Users\klaus\AppData\Roaming\go\env                                                                                                
set GOEXE=.exe                                                                                                                                 
set GOFLAGS=                                                                                                                                   
set GOHOSTARCH=amd64                                                                                                                           
set GOHOSTOS=windows                                                                                                                           
set GONOPROXY=                                                                                                                                 
set GONOSUMDB=                                                                                                                                 
set GOOS=windows                                                                                                                               
set GOPATH=e:\gopath                                                                                                                           
set GOPRIVATE=                                                                                                                                 
set GOPROXY=https://goproxy.io                                                                                                                 
set GOROOT=c:\go                                                                                                                               
set GOSUMDB=sum.golang.org                                                                                                                     
set GOTMPDIR=                                                                                                                                  
set GOTOOLDIR=c:\go\pkg\tool\windows_amd64                                                                                                     
set GCCGO=gccgo                                                                                                                                
set AR=ar                                                                                                                                      
set CC=gcc                                                                                                                                     
set CXX=g++                                                                                                                                    
set CGO_ENABLED=1                                                                                                                              
set GOMOD=                                                                                                                                     
set CGO_CFLAGS=-g -O2                                                                                                                          
set CGO_CPPFLAGS=                                                                                                                              
set CGO_CXXFLAGS=-g -O2                                                                                                                        
set CGO_FFLAGS=-g -O2                                                                                                                          
set CGO_LDFLAGS=-g -O2                                                                                                                         
set PKG_CONFIG=pkg-config                                                                                                                      
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=d:\temp\wintemp\go-build155272862=/tmp/go-build -gno-record-gcc-switches   

What did you do?

Run benchmark: https://play.golang.org/p/WeuJg6yaOuJ

go test -bench=. -test.benchtime=10s used to test.

What did you expect to see?

Close or similar benchmark speeds.

What did you see instead?

40% performance regression.

λ benchcmp go113.txt go114.txt
benchmark                                       old ns/op     new ns/op     delta
BenchmarkCompressAllocationsSingle/flate-32     87026         121741        +39.89%
BenchmarkCompressAllocationsSingle/gzip-32      88654         122632        +38.33%

This is not a purely theoretical benchmark. While suboptimal, this is the easiest way to compress a piece of data, so this will be seen in the wild. It could also indicate a general regression for applications allocating a lot.

Edit: This is not related to changes in the referenced packages. Seeing this when using packages outside the stdlib as well.

[klauspost]

Somebody proposed to remove 'ReportAllocs'. It has an impact, but not very big:

λ benchcmp go113-no.txt go114-no.txt
benchmark                                       old ns/op     new ns/op     delta
BenchmarkCompressAllocationsSingle/flate-32     88082         117794        +33.73%
BenchmarkCompressAllocationsSingle/gzip-32      89279         118946        +33.23%

[klauspost]

Turning off DEP seems to reduce the impact, but still considerably slower:

λ bcdedit.exe /set {current} nx AlwaysOff -> Reboot. Confirm setting with λ wmic OS Get DataExecutionPrevention_SupportPolicy -> 0.

λ benchcmp go113-depoff.txt go114-depoff.txt
benchmark                                       old ns/op     new ns/op     delta
BenchmarkCompressAllocationsSingle/flate-32     87619         107249        +22.40%
BenchmarkCompressAllocationsSingle/gzip-32      89344         107670        +20.51%

This actually matches my initial measurements before isolating the issue, so I am unsure if this is just some variance based on system state.

[josharian]

cc @mknyszek

[cagedmantis]

/cc @aclements @rsc @randall77

[mknyszek]

The regression in the benchmark is reproducible on Linux (but to a lesser extent).

[mknyszek]

Or... hm. I spoke too soon. 5 runs shows that the benchmark is pretty noisy on Linux and it's not obvious that there's a regression.

name                                old time/op    new time/op    delta
CompressAllocationsSingle/flate-48     182µs ±12%     169µs ± 4%    ~     (p=0.151 n=5+5)
CompressAllocationsSingle/gzip-48      170µs ± 7%     184µs ± 9%    ~     (p=0.056 n=5+5)

name                                old alloc/op   new alloc/op   delta
CompressAllocationsSingle/flate-48     814kB ± 0%     814kB ± 0%  +0.00%  (p=0.016 n=4+5)
CompressAllocationsSingle/gzip-48      814kB ± 0%     814kB ± 0%  +0.00%  (p=0.008 n=5+5)

name                                old allocs/op  new allocs/op  delta
CompressAllocationsSingle/flate-48      16.0 ± 0%      16.0 ± 0%    ~     (all equal)
CompressAllocationsSingle/gzip-48       17.0 ± 0%      17.0 ± 0%    ~     (all equal)

That's what I get for making conclusions on just one benchmark run. This probably needs many more runs to see a concrete difference, if one exists.

Since this seems much more easily reproducible on Windows, I'm going to try there.

[leafrhythms]

Cannot reproduce on linux.

$ go env

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/leaf/.cache/go-build"
GOENV="/home/leaf/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/leaf/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/lib/go-1.14"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go-1.14/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build636896530=/tmp/go-build -gno-record-gcc-switches" 

$ ~/go/bin/benchstat bench_1.1{3,4}.txt

name old time/op new time/op delta
CompressAllocationsSingle/flate-8 180µs ± 2% 181µs ± 4% ~ (p=1.000 n=10+10)
CompressAllocationsSingle/gzip-8 183µs ± 7% 204µs ± 1% +11.38% (p=0.000 n=9+10)

Edit: benchmark run with ReportAlloc removed.

[mknyszek]

While I set up my Windows environment: @klauspost what suggests to you that this is a regression in allocation performance vs. something else?

[klauspost]

@mknyszek It is only really doing allocations. The compression part is trivial, but it needs enough content to activate all allocations.

Profiles: alloc-pprof.zip

λ go tool pprof cpu113.pprof
Type: cpu
Time: Feb 26, 2020 at 5:05pm (CET)
Duration: 25.46s, Total samples = 1.01mins (238.80%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 39.56s, 65.07% of 60.80s total
Dropped 227 nodes (cum <= 0.30s)
Showing top 10 nodes out of 144
      flat  flat%   sum%        cum   cum%
    11.28s 18.55% 18.55%     14.95s 24.59%  runtime.scanobject
     5.51s  9.06% 27.62%      5.54s  9.11%  runtime.stdcall2
     4.86s  7.99% 35.61%      4.86s  7.99%  runtime.runGCProg
     4.76s  7.83% 43.44%      4.76s  7.83%  runtime.memclrNoHeapPointers
     3.82s  6.28% 49.72%      3.83s  6.30%  runtime.stdcall3
        2s  3.29% 53.01%      2.03s  3.34%  runtime.runqgrab
     1.97s  3.24% 56.25%      1.97s  3.24%  runtime.procyield
     1.94s  3.19% 59.44%      1.96s  3.22%  runtime.(*lfstack).pop
     1.86s  3.06% 62.50%      1.90s  3.12%  runtime.stdcall1
     1.56s  2.57% 65.07%     21.19s 34.85%  runtime.gcDrain

λ go tool pprof cpu114.pprof
Type: cpu
Time: Feb 26, 2020 at 5:07pm (CET)
Duration: 26.61s, Total samples = 1.34mins (303.24%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 1.07mins, 79.31% of 1.34mins total
Dropped 271 nodes (cum <= 0.01mins)
Showing top 10 nodes out of 95
      flat  flat%   sum%        cum   cum%
  0.54mins 40.51% 40.51%   0.55mins 40.59%  runtime.stdcall2
  0.17mins 12.93% 53.43%   0.22mins 16.34%  runtime.scanobject
  0.12mins  8.99% 62.42%   0.12mins  8.99%  runtime.memclrNoHeapPointers
  0.08mins  5.94% 68.36%   0.08mins  6.00%  runtime.stdcall1
  0.07mins  4.87% 73.23%   0.07mins  4.87%  runtime.runGCProg
  0.02mins  1.65% 74.88%   0.02mins  1.65%  runtime.procyield
  0.02mins  1.28% 76.15%   0.02mins  1.28%  runtime.runqgrab
  0.02mins  1.17% 77.32%   0.02mins  1.18%  runtime.stdcall7
  0.01mins  1.00% 78.32%   0.02mins  1.61%  runtime.greyobject
  0.01mins  0.99% 79.31%   0.03mins  1.90%  runtime.findObject

[klauspost]

SVGs:

Go 1.13: https://files.klauspost.com/profile002.svg
Go 1.14: https://files.klauspost.com/profile001.svg