<p dir="auto">I've initially spotted this in gperftools as this affects all users of SIGPROF. The problem is that SIGPROF is delivered to process, which translates to "any thread that isn't blocking SIGROF". Luckily for us, in practice it becomes "thread that is running now". But if there are several running threads something within kernel is making it choose one thread more often than another.</p>
<p dir="auto">The test program at <a href="https://gist.github.com/alk/568c0465f4f208196d8b">https://gist.github.com/alk/568c0465f4f208196d8b</a> makes it very easy to reproduce. This program spawns two goroutines that do nothing but burn CPU.</p>
<p dir="auto">When profiled with perf:</p>
<p dir="auto">$ perf record ./goprof-test; perf report</p>
<p dir="auto">I see correct 50/50 division of profiling ticks between two goroutines, since on multicore machine go runtime runs two goroutines on two OS threads which kernel run in parallel on two different cores.</p>
<p dir="auto">When profiling with runtime/pprof:</p>
<p dir="auto">$ CPUPROFILE=goprof-test-prof ./goprof-test ; pprof --web ./goprof-test ./goprof-test-prof</p>
<p dir="auto">I see as much skew as 80/20.</p>
<p dir="auto">This is exactly same behavior that I've seen with gperftools (and google3's profiler).</p>
<p dir="auto">For most programs it apparently doesn't matter. But for programs that have distinct pools of threads doing very different work, this may cause real problems. Particularly, I've seen this (with gperftools) to cause very skewed profiles for Couchbase's memcached binary where they have small pool of network worker threads and another pool of IO worker threads.</p>
<p dir="auto">In gperftools I've implemented workaround which creates per-thread timers that "tick" on corresponding thread's cpu time. But I don't think it's scalable enough to be made default (and another problem but arguably specific for gperftools is that all threads have to call ProfilerRegisterThread again). You can see my implementation at: <a href="https://github.com/gperftools/gperftools/blob/master/src/profile-handler.cc">https://github.com/gperftools/gperftools/blob/master/src/profile-handler.cc</a> (parts that are under HAVE_LINUX_SIGEV_THREAD_ID defined)</p>
<p dir="auto">I've seen this behavior on FreeBSD VMs too, but don't know about other OSes.</p>
<p dir="auto">Maybe there is better way to avoid this skew or maybe we should just ask kernel folks to change SIGPROF signal delivery to avoid this skew. In any case this is bug worth tracking.</p>
<p dir="auto">This is somewhat related, but distinct issue from <a class="issue-link js-issue-link" data-error-text="Failed to load title" data-id="125202044" data-permission-text="Title is private" data-url="https://github.com/golang/go/issues/13841" data-hovercard-type="issue" data-hovercard-url="/golang/go/issues/13841/hovercard" href="https://github.com/golang/go/issues/13841">#13841</a></p>
<h3 dir="auto">What version of Go are you using (<code class="notranslate">go version</code>)?</h3>
<pre class="notranslate">$ go1.13 version
go version go1.13.3 darwin/amd64
</pre>
<h3 dir="auto">Does this issue reproduce with the latest release?</h3>
<p dir="auto">Yes, this is present in Go 1.13 and in current tip with Linux 4.14. It seems to exist even back in Go 1.4, and with Linux 3.2 and 2.6.32.</p>
<p dir="auto">Am I holding it wrong?</p>
<p dir="auto">Around Go 1.6, a lot of the tests in runtime/pprof were called out as being flaky. It looks like around that same time, the builders got an overhaul. Maybe they moved to machines with more CPU cores than before, and the increase in flakiness was due to some SIGPROF deliveries being skipped?</p>
<p dir="auto">The tests in runtime/pprof both now and around Go 1.6 seem to compare parts of the profile to itself, but not to the CPU usage reported by the operating system. If this is a real bug, those tests would not have discovered it.</p>
<h3 dir="auto">What operating system and processor architecture are you using (<code class="notranslate">go env</code>)?</h3>
<p dir="auto">I'm compiling on darwin/amd64 and running on linux/amd64.</p>
<details><summary><code class="notranslate">go env</code> Output</summary><br><pre class="notranslate">$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/rhys/Library/Caches/go-build"
GOENV="/Users/rhys/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY="*"
GONOSUMDB="*"
GOOS="darwin"
GOPATH="/Users/rhys/go"
GOPRIVATE="*"
GOPROXY="direct"
GOROOT="/usr/local/go"
GOSUMDB="off"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/49/zmds5zsn75z1283vtzxyfr5hj7yjq4/T/go-build343144681=/tmp/go-build -gno-record-gcc-switches -fno-common"
</pre></details>
<h3 dir="auto">What did you do?</h3>
<p dir="auto">I looked at a CPU profile for a Go program running on a Linux machine where <code class="notranslate">top</code> reported 20 cores of CPU usage (2000%), but the profile showed about 240% / 2.4 cores of usage.</p>
<p dir="auto">I ran a test with the <code class="notranslate">-test.cpuprofile</code> flag on a Linux machine and compared the results of the <code class="notranslate">time</code> shell built-in with <code class="notranslate">go tool pprof</code>'s view of the usage. I varied the rate that the program asked the kernel to deliver SIGPROF and found that the two measurements agreed on the number of CPU cycles spent as long as there were fewer than 250 SIGPROF deliveries per second.</p>
<p dir="auto">I ran the test under <code class="notranslate">perf stat -e 'signal:*'</code> and found that its count of <code class="notranslate">signal:signal_generate</code> events lined up with the number of SIGPROF deliveries I'd expect, that its count of <code class="notranslate">signal:signal_deliver</code> events lined up with the number of samples in the CPU profile, and that the two matched well only when the "generate" rate was less than 250 samples per second.</p>
<hr>
<p dir="auto">Here, the test uses 96 vCPUs of a machine with 96 hyperthreads for 10 seconds, using the Go runtime's default profile rate of 100 Hz. The Linux kernel generates slightly less than 96,000 signals (which are probably all SIGPROF). The <code class="notranslate">time</code> built-in reports slightly less than 16 minutes (960 seconds) of "user" CPU. That's good.</p>
<p dir="auto">The resulting profile shows 10.20 seconds of wall-clock time and 1.61 minutes (about 96.6 seconds) of CPU time, or about 9660 samples at 100 Hz. That's close to the number of signals that the kernel reports it delivered to the program, but that doesn't match the number generated by the kernel or the actual CPU time spent.</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="$ time sudo perf stat -e 'signal:*' ./test-n -test.cpuprofile=./prof-n -test.cpu=96
PASS

 Performance counter stats for './test-n -test.cpuprofile=./prof-n -test.cpu=96':

            95,690      signal:signal_generate                                      
             9,688      signal:signal_deliver                                       

      10.211210687 seconds time elapsed


real	0m10.316s
user	15m57.840s
sys	0m0.045s
$ go tool pprof -text /tmp/test-n /tmp/prof-n 
File: test-n
Type: cpu
Time: Oct 21, 2019 at 2:16pm (PDT)
Duration: 10.20s, Total samples = 1.61mins (949.83%)
Showing nodes accounting for 1.61mins, 100% of 1.61mins total
Dropped 13 nodes (cum &lt;= 0.01mins)
      flat  flat%   sum%        cum   cum%
  1.61mins   100%   100%   1.61mins   100%  command-line-arguments.cpuHog1
         0     0%   100%   1.61mins   100%  command-line-arguments.TestCPUProfile.func1
         0     0%   100%   1.61mins   100%  command-line-arguments.cpuHogger"><pre class="notranslate"><code class="notranslate">$ time sudo perf stat -e 'signal:*' ./test-n -test.cpuprofile=./prof-n -test.cpu=96
PASS

 Performance counter stats for './test-n -test.cpuprofile=./prof-n -test.cpu=96':

            95,690      signal:signal_generate                                      
             9,688      signal:signal_deliver                                       

      10.211210687 seconds time elapsed


real	0m10.316s
user	15m57.840s
sys	0m0.045s
$ go tool pprof -text /tmp/test-n /tmp/prof-n 
File: test-n
Type: cpu
Time: Oct 21, 2019 at 2:16pm (PDT)
Duration: 10.20s, Total samples = 1.61mins (949.83%)
Showing nodes accounting for 1.61mins, 100% of 1.61mins total
Dropped 13 nodes (cum &lt;= 0.01mins)
      flat  flat%   sum%        cum   cum%
  1.61mins   100%   100%   1.61mins   100%  command-line-arguments.cpuHog1
         0     0%   100%   1.61mins   100%  command-line-arguments.TestCPUProfile.func1
         0     0%   100%   1.61mins   100%  command-line-arguments.cpuHogger
</code></pre></div>
<p dir="auto">Calling <code class="notranslate">runtime.SetCPUProfileRate</code> with "2 Hz" right before the testing package's CPU profile starts lets me dial the profile rate down to less than 250 Hz process-wide. (The warning message seems harmless in this case.) This leads to the kernel's measurements of "signal:signal_generate" and "signal:signal_deliver" matching each other, and for <code class="notranslate">go tool pprof</code>'s measurement of "15.94mins" to come very close to what the <code class="notranslate">time</code> built-in sees at "user	15m57.048s".</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="$ time sudo env PROFILE_HZ=2 perf stat -e 'signal:*' ./test-n -test.cpuprofile=./prof-n -test.cpu=96
runtime: cannot set cpu profile rate until previous profile has finished.
PASS

 Performance counter stats for './test-n -test.cpuprofile=./prof-n -test.cpu=96':

             1,913      signal:signal_generate                                      
             1,913      signal:signal_deliver                                       

      10.120272912 seconds time elapsed


real	0m10.221s
user	15m57.048s
sys	0m0.378s
$ go tool pprof -text /tmp/test-n /tmp/prof-n 
File: test-n
Type: cpu
Time: Oct 21, 2019 at 2:17pm (PDT)
Duration: 10.11s, Total samples = 15.94mins (9464.52%)
Showing nodes accounting for 15.93mins, 99.90% of 15.94mins total
Dropped 1 node (cum &lt;= 0.08mins)
      flat  flat%   sum%        cum   cum%
 15.93mins 99.90% 99.90%  15.93mins 99.90%  command-line-arguments.cpuHog1
         0     0% 99.90%  15.93mins 99.90%  command-line-arguments.TestCPUProfile.func1
         0     0% 99.90%  15.93mins 99.90%  command-line-arguments.cpuHogger"><pre class="notranslate"><code class="notranslate">$ time sudo env PROFILE_HZ=2 perf stat -e 'signal:*' ./test-n -test.cpuprofile=./prof-n -test.cpu=96
runtime: cannot set cpu profile rate until previous profile has finished.
PASS

 Performance counter stats for './test-n -test.cpuprofile=./prof-n -test.cpu=96':

             1,913      signal:signal_generate                                      
             1,913      signal:signal_deliver                                       

      10.120272912 seconds time elapsed


real	0m10.221s
user	15m57.048s
sys	0m0.378s
$ go tool pprof -text /tmp/test-n /tmp/prof-n 
File: test-n
Type: cpu
Time: Oct 21, 2019 at 2:17pm (PDT)
Duration: 10.11s, Total samples = 15.94mins (9464.52%)
Showing nodes accounting for 15.93mins, 99.90% of 15.94mins total
Dropped 1 node (cum &lt;= 0.08mins)
      flat  flat%   sum%        cum   cum%
 15.93mins 99.90% 99.90%  15.93mins 99.90%  command-line-arguments.cpuHog1
         0     0% 99.90%  15.93mins 99.90%  command-line-arguments.TestCPUProfile.func1
         0     0% 99.90%  15.93mins 99.90%  command-line-arguments.cpuHogger
</code></pre></div>
<p dir="auto">I confirmed that the kernel was configured with high-resolution timers as recommended in <a class="issue-link js-issue-link" data-error-text="Failed to load title" data-id="125202044" data-permission-text="Title is private" data-url="https://github.com/golang/go/issues/13841" data-hovercard-type="issue" data-hovercard-url="/golang/go/issues/13841/hovercard" href="https://github.com/golang/go/issues/13841">#13841</a>.</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="$ uname -a
Linux ip-172-31-18-196.us-west-2.compute.internal 4.14.123-111.109.amzn2.x86_64 #1 SMP Mon Jun 10 19:37:57 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
$ cat /boot/config-$(uname -r) | grep CONFIG_HIGH_RES_TIMERS
CONFIG_HIGH_RES_TIMERS=y
$ cat /boot/config-$(uname -r) | grep ^CONFIG_HZ
CONFIG_HZ_250=y
CONFIG_HZ=250"><pre class="notranslate"><code class="notranslate">$ uname -a
Linux ip-172-31-18-196.us-west-2.compute.internal 4.14.123-111.109.amzn2.x86_64 #1 SMP Mon Jun 10 19:37:57 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
$ cat /boot/config-$(uname -r) | grep CONFIG_HIGH_RES_TIMERS
CONFIG_HIGH_RES_TIMERS=y
$ cat /boot/config-$(uname -r) | grep ^CONFIG_HZ
CONFIG_HZ_250=y
CONFIG_HZ=250
</code></pre></div>
<p dir="auto">I've seen this effect both on virtual machines and on physical hardware. (Most of my follow-up testing has taken place on virtual machines.)</p>
<h3 dir="auto">What did you expect to see?</h3>
<p dir="auto">I expected the number of seconds of CPU time reported by <code class="notranslate">go tool pprof</code> to align with the number of seconds of CPU time observed by the kernel.</p>
<p dir="auto">When I run <code class="notranslate">go tool pprof</code>, I expect the time reported in the "Duration" line (like "Duration: 5.11s, Total samples = 8.50s (166.40%)") to match what I'd see from looking at a tool like <code class="notranslate">top</code> at the same time.</p>
<h3 dir="auto">What did you see instead?</h3>
<p dir="auto">The Linux kernel seems to drop SIGPROF events when they come more than 250 times per second. I don't know if it drops them fairly—the profiles might be skewed.</p>
<hr>
<h3 dir="auto">Open questions</h3>
<p dir="auto">Is there a simple setting that my coworkers and I are missing? I've reproduced this with vanilla machine images for Ubuntu and Amazon Linux 2.</p>
<p dir="auto">Is the right move for <code class="notranslate">runtime.SetCPUProfileRate</code> to limit its input to <code class="notranslate">250 / GOMAXPROCS</code>?</p>
<p dir="auto">Does the number "250" come from Linux's <code class="notranslate">CONFIG_HZ_250=y</code> / <code class="notranslate">CONFIG_HZ=250</code>, and is it right for that configuration to end up compiled in to Go?</p>
<p dir="auto">Thanks!</p>
<hr>
<p dir="auto">Here's the test program:</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="package repro

import (
	&quot;os&quot;
	&quot;runtime&quot;
	&quot;strconv&quot;
	&quot;sync&quot;
	&quot;sync/atomic&quot;
	&quot;testing&quot;
	&quot;time&quot;
)

var sink int64

func init() {
	hz, _ := strconv.Atoi(os.Getenv(&quot;PROFILE_HZ&quot;))
	if hz &gt; 0 {
		runtime.SetCPUProfileRate(hz)
	}
}

func TestCPUProfile(t *testing.T) {
	workers := runtime.GOMAXPROCS(0)

	var wg sync.WaitGroup
	for i := 0; i &lt; workers; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()

			var v int
			cpuHogger(cpuHog1, &amp;v, 10*time.Second)
			atomic.StoreInt64(&amp;sink, int64(v))
		}()
	}

	wg.Wait()
}

// cpuHogger and cpuHog1 from src/runtime/pprof/pprof_test.go

func cpuHogger(f func(x int) int, y *int, dur time.Duration) {
	// We only need to get one 100 Hz clock tick, so we've got
	// a large safety buffer.
	// But do at least 500 iterations (which should take about 100ms),
	// otherwise TestCPUProfileMultithreaded can fail if only one
	// thread is scheduled during the testing period.
	t0 := time.Now()
	accum := *y
	for i := 0; i &lt; 500 || time.Since(t0) &lt; dur; i++ {
		accum = f(accum)
	}
	*y = accum
}

// The actual CPU hogging function.
// Must not call other functions nor access heap/globals in the loop,
// otherwise under race detector the samples will be in the race runtime.
func cpuHog1(x int) int {
	foo := x
	for i := 0; i &lt; 1e5; i++ {
		if foo &gt; 0 {
			foo *= foo
		} else {
			foo *= foo + 1
		}
	}
	return foo
}"><pre class="notranslate"><code class="notranslate">package repro

import (
	"os"
	"runtime"
	"strconv"
	"sync"
	"sync/atomic"
	"testing"
	"time"
)

var sink int64

func init() {
	hz, _ := strconv.Atoi(os.Getenv("PROFILE_HZ"))
	if hz &gt; 0 {
		runtime.SetCPUProfileRate(hz)
	}
}

func TestCPUProfile(t *testing.T) {
	workers := runtime.GOMAXPROCS(0)

	var wg sync.WaitGroup
	for i := 0; i &lt; workers; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()

			var v int
			cpuHogger(cpuHog1, &amp;v, 10*time.Second)
			atomic.StoreInt64(&amp;sink, int64(v))
		}()
	}

	wg.Wait()
}

// cpuHogger and cpuHog1 from src/runtime/pprof/pprof_test.go

func cpuHogger(f func(x int) int, y *int, dur time.Duration) {
	// We only need to get one 100 Hz clock tick, so we've got
	// a large safety buffer.
	// But do at least 500 iterations (which should take about 100ms),
	// otherwise TestCPUProfileMultithreaded can fail if only one
	// thread is scheduled during the testing period.
	t0 := time.Now()
	accum := *y
	for i := 0; i &lt; 500 || time.Since(t0) &lt; dur; i++ {
		accum = f(accum)
	}
	*y = accum
}

// The actual CPU hogging function.
// Must not call other functions nor access heap/globals in the loop,
// otherwise under race detector the samples will be in the race runtime.
func cpuHog1(x int) int {
	foo := x
	for i := 0; i &lt; 1e5; i++ {
		if foo &gt; 0 {
			foo *= foo
		} else {
			foo *= foo + 1
		}
	}
	return foo
}
</code></pre></div>