Repository: go
Issue: runtime: cgo calls are way faster when enabling CPU profile
Labels: Performance,NeedsInvestigation,compiler/runtime

### What version of Go are you using (`go version`)?

<pre>
$ go version
go version go1.14.2 linux/amd64
</pre>

### Does this issue reproduce with the latest release?

It was present with 1.13.4 and uprading to latest release confirms it

### What operating system and processor architecture are you using (`go env`)?

<details><summary><code>go env</code> Output</summary><br><pre>
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/j-lallement/.cache/go-build"
GOENV="/home/j-lallement/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/j-lallement/.go/"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/j-lallement/Ubuntu/Dev/zfs/zsys/go.mod"
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-build141739689=/tmp/go-build -gno-record-gcc-switches"
</pre></details>

### What did you do?

1. We started having a contention on some of our code (https://github.com/ubuntu/zsys) which is using go-libzfs when opening the ZFS pools.

This issues a lot of cgo calls to a library which then proceed to syscall. We expected some performance issues.

2. The following code:
```
dsZFS, err := newZ.libzfs.DatasetOpenAll()
if err != nil {
    return fmt.Errorf(i18n.G("can't list datasets: %v"), err)
}
```
Was running for 13.5s in average in our system (with a lot of datasets)

3. We thus wanted to start doing CPU profile and did:
```
f, _ := os.Create("/tmp/cpuprofile")
defer f.Close()
pprof.StartCPUProfile(f)
dsZFS, err := newZ.libzfs.DatasetOpenAll()
if err != nil {
    return fmt.Errorf(i18n.G("can't list datasets: %v"), err)
}
pprof.StopCPUProfile()
```
The surprise was that the whole call was then taking less than a second! This is fully reproducible on our machine: No change apart from enabling or disabling CPU profile goes from 13.5s without CPU profile to one second with it enabled.
[cpu.pprof.txt](https://github.com/golang/go/files/4455704/cpu.pprof.txt)

The result of DatasetOpenAll isn’t identical with and without CPU profile enabled, there are less objects returns (see the difference in call stack of number of `openchildren`)

4. We started to trace without and with CPU profile enabled. This confirms the time difference:

a. Without CPU Profile enabled:
```
t, _ := os.Create("/tmp/trace")
defer t.Close()
//f, _ := os.Create("/tmp/cpuprofile")
//defer f.Close()
//pprof.StartCPUProfile(f)
trace.Start(t)
dsZFS, err := newZ.libzfs.DatasetOpenAll()
if err != nil {
    return fmt.Errorf(i18n.G("can't list datasets: %v"), err)
}
trace.Stop()
//pprof.StopCPUProfile()
```

Here is the trace (taking 15s): [trace_without_cpuprofile.txt](https://github.com/golang/go/files/4455742/trace_without_cpuprofile.txt)

b. With CPU Profile enabled:
```
t, _ := os.Create("/tmp/trace")
defer t.Close()
f, _ := os.Create("/tmp/cpuprofile")
defer f.Close()
pprof.StartCPUProfile(f)
trace.Start(t)
dsZFS, err := newZ.libzfs.DatasetOpenAll()
if err != nil {
    return fmt.Errorf(i18n.G("can't list datasets: %v"), err)
}
trace.Stop()
pprof.StopCPUProfile()
```

Here is the trace (taking 3s): [trace_with_cpuprofile.txt](https://github.com/golang/go/files/4455739/trace_with_cpuprofile.txt)

There is a little bit more on the 15s trace of GC calls, but nothing drastic that can explain the difference (38ms vs 4.4ms). We can see there is a lot more gaps though in Execution time.
The other surprise is that we are blocking way more in syscalls (2.3s vs 0.4s).

https://github.com/bicomsystems/go-libzfs doesn’t seem to do anything particular in case it detects it’s being under profile, is there anything CPU profiler is doing to influence the Cgo calls or am I missing anything obvious?