Repository: go
Issue: cmd/pprof: macOS 12.6.1 profile overcounts system calls (again)
Labels: OS-Darwin,NeedsInvestigation,compiler/runtime

### What version of Go are you using (`go version`)?

<pre>
$ go version
go version go1.19.4 darwin/arm64
</pre>

This is on macOS 12.6.1 with an M1 chip, but the problem seems to affect [Intel as well](https://github.com/golang/go/issues/57722#issuecomment-1377755284).

### Does this issue reproduce with the latest release?

Yes.

### What operating system and processor architecture are you using (`go env`)?

<details><summary><code>go env</code> Output</summary><br><pre>
$ go env
GO111MODULE="auto"
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/MyUser/Library/Caches/go-build"
GOENV="/Users/MyUser/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS="-count=1"
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/MyUser/go/pkg/mod"
GONOPROXY="github.com/MyOrg"
GONOSUMDB="github.com/MyOrg,go.myorg.io"
GOOS="darwin"
GOPATH="/Users/MyUser/go"
GOPRIVATE="github.com/MyOrg"
GOPROXY="binaries.myorg.io,https://proxy.golang.org,direct"
GOROOT="/opt/homebrew/Cellar/go/1.19.4/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/opt/homebrew/Cellar/go/1.19.4/libexec/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.19.4"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/MyUser/go/src/github.com/felixge/macos-profiler-bias/go.mod"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/0t/nwrdnfnd2mjdgr0z_p_f6xww0000gq/T/go-build3012663781=/tmp/go-build -gno-record-gcc-switches -fno-common"
</pre></details>

### What did you do?

Create a CPU profile of a CPU-bound workload that is interleaved with short system calls.

For example [TestInterleavedIO](https://gist.github.com/felixge/f99014dac01401ab7f273532b1c024f3#file-macos_pprof_bias-go-L11-L36) is a reproducer that is compressing a 250MB file containing random data.

### What did you expect to see?

A profile that is similar to the one shown below for linux. Most of time should be spent on gzip compression, and a little bit on syscalls.

<img width="1267" alt="interleaved linux" src="https://user-images.githubusercontent.com/15000/211587271-839af0c4-427d-48ba-8483-4853b9894757.png">

### What did you see instead?

On macOS the majority of time is attributed to read and write syscalls. The gzip compression is barely showing up at all.

<img width="1262" alt="interleaved darwin" src="https://user-images.githubusercontent.com/15000/211587408-bd50d383-2c0e-493a-b3f0-81f58de7f883.png">

### Sanity Check

[TestSequentialIO](https://gist.github.com/felixge/f99014dac01401ab7f273532b1c024f3#file-macos_pprof_bias-go-L38-L59) implements the same workload, but instead of interleaved I/O, it does one big read first, followed by gzip compression, followed by a big write.

As expected, Linux produces a profile dominated by gzip compression.
 
<img width="1265" alt="sequential linux pprof" src="https://user-images.githubusercontent.com/15000/211588974-2aab98bd-3ad4-45d7-a864-6664c7053a0e.png">

And macOS now shows the right profile too.

<img width="1267" alt="sequential darwin pprof" src="https://user-images.githubusercontent.com/15000/211589015-aaab7179-d2b3-43d7-ba45-01e63fbf220e.png">

### Conclusion

macOS `setitimer(2)` seems to bias towards syscalls. This issue was reported and fixed in the past, see https://github.com/golang/go/issues/17406 (2016) and https://github.com/golang/go/issues/6047 (2013). So this could be a macOS regression.

I've uploaded all code, pprofs and screenshots to this [google drive folder](https://drive.google.com/drive/folders/1ND2BbqPruC9Y8zCTdiPdFUEGmMBWcJ75?usp=sharing).