runtime/pprof: Golang pprof cpu performance analysis, after the sampling frequency increases on the windows platform, the number of samples decreases

[ypcd]

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

go version go1.20.6 windows/amd64

Does this issue reproduce with the latest release?

yes

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

windows/amd64
windows11 (22H2, 22621.1992)
cpu x86 amd pyzen 5500

What did you do?

I want to increase the sampling frequency of cpu profiling and get more cpu sampling samples.
On the windows platform, I use the runtime.SetCPUProfileRate() interface to set the cpu performance analysis sampling frequency.
It was found that after increasing the sampling frequency, the number of cpu samples (Total samples) decreased abnormally.
When the computer is running the test program, the total CPU usage does not exceed 50%.

I tested again on the same computer using linux (centos stream 9, 5.14.0-340.el9.x86_64) through a virtual machine, and found that the sampling results were basically the same, and the results were normal.

Test code:

package main

import (
	"fmt"
	"os"
	"runtime"
	"runtime/pprof"
	"time"
)

func inrun1() {
	t1 := time.Now()
	for {
		if time.Since(t1) > time.Second*3 {
			return
		}
	}
}

func main() {
	samplesNum := 100
	fn := fmt.Sprintf("cpuprof-%d--%s--main.prof", samplesNum, runtime.GOOS)
	f, err := os.Create(fn)
	if err != nil {
		panic(err)
	}
	defer f.Close()
	runtime.SetCPUProfileRate(samplesNum)
	pprof.StartCPUProfile(f)

	inrun1()

	pprof.StopCPUProfile()
}

What did you expect to see?

I want to increase the sampling frequency of cpu profiling and get more cpu sampling samples.

What did you see instead?

It was found that after increasing the sampling frequency, the number of cpu samples (Total samples) decreased abnormally.
When the computer is running the test program, the total CPU usage does not exceed 50%.

I tested again on the same computer using linux (centos stream 9, 5.14.0-340.el9.x86_64) through a virtual machine, and found that the sampling results were basically the same, and the results were normal.

Specific sampling results:
windows11 (22H2, 22621.1992):
Sampling frequency Sampling result
25 Duration: 3.08s, Total samples = 2.92s (94.68%)
50 Duration: 3.19s, Total samples = 3s (93.94%)
100 Duration: 3.16s, Total samples = 1.91s (60.48%)
200 Duration: 3.18s, Total samples = 960ms (30.20%)

linux --centos-stream 9, 5.14.0-340.el9.x86_64:
Sampling frequency Sampling result
25 Duration: 3.13s, Total samples = 2.84s (90.68%)
50 Duration: 3.13s, Total samples = 2.84s (90.71%)
100 Duration: 3.13s, Total samples = 2.85s (91.06%)
200 Duration: 3.13s, Total samples = 2.85s (91.01%)

[dr2chase]

"When the computer is running the test program, the total CPU usage does not exceed 50%."

What is the total CPU usage on Linux? (I.e., is this information supposed to tell us

1. that there is plenty of available CPU to collect samples, or
2. that changing the sampling frequency somehow caused the CPU to not run at full utilization, on Windows 11?

And I assume that you first observed this with a not-toy program, instead of a tight loop checking the current time. Is that assumption correct?

[dr2chase]

@qmuntal are there any well-known windows gotchas that might cause this?

[qmuntal]

@qmuntal are there any well-known windows gotchas that might cause this?

It is related to #44343. The maximum sampling rate that doesn't reduce the number of samples is ~60, that is one sample every ~16ms, which matches the default Windows time accuracy. I've have reproduced @ypcd results, and managed to get back the number of samples to ~96% by calling timeBeginPeriod(1) before starting the sampling: https://play.golang.com/p/vFcMKDVmWrE.

What I don't know is why the number of samples are reduced. Could it be that the Go runtime is expecting the OS to honor the sampling rate, and when this assumption is not met it doesn't behaves well?

[qmuntal]

Submitted CL 514375, which fixes this issue by using high resolution timers for CPU sampling.

[gopherbot]

Change https://go.dev/cl/514375 mentions this issue: runtime: cpu profiler to use high resolution timers on Windows

[ypcd]

"When the computer is running the test program, the total CPU usage does not exceed 50%."

What is the total CPU usage on Linux? (I.e., is this information supposed to tell us

1. that there is plenty of available CPU to collect samples, or
2. that changing the sampling frequency somehow caused the CPU to not run at full utilization, on Windows 11?

And I assume that you first observed this with a not-toy program, instead of a tight loop checking the current time. Is that assumption correct?

When I run tests on different platforms (windows, linux), the computer has enough free cpu time to use.
The total cpu usage on linux is below 50%.
Changing the sampling frequency seems to have no effect on the operation of the main body of the program, which can be proved by the fact that the duration of the program is more than 3 seconds. Changing the sampling frequency has an effect on the number of samples.

I first discovered this problem while profiling other programs.
Test programs are now written for individual tests.

[ypcd]

I rewrote the test program a bit. I also found the sample reduction problem in the pure calculation test program.

Specific performance:
Sampling frequency Number of samples
25 Duration: 2.55s, Total samples = 2.44s (95.58%)
50 Duration: 2.54s, Total samples = 2.42s (95.45%)
100 Duration: 2.59s, Total samples = 1.52s (58.72%)
200 Duration: 2.53s, Total samples = 780ms (30.78%)

Pure calculation test program:

package main

import (
	"fmt"
	"os"
	"runtime"
	"runtime/pprof"
	"testing"
	"time"
)

func inrun2() int {
	v := 0
	for i := 0; i < 10000*10000*100; i++ {
		v = i * (i - 1)
	}
	return v
}

func cpuprofile(samplesNum int) {
	fn := fmt.Sprintf("cpuprof-%d--%s--i.prof", samplesNum, runtime.GOOS)
	f, err := os.Create(fn)
	if err != nil {
		panic(err)
	}
	defer f.Close()
	runtime.SetCPUProfileRate(samplesNum)
	pprof.StartCPUProfile(f)

	v := inrun2()
	_ = v

	pprof.StopCPUProfile()

}

func Test_cpuprofile25(t *testing.T)  { cpuprofile(25) }
func Test_cpuprofile50(t *testing.T)  { cpuprofile(50) }
func Test_cpuprofile100(t *testing.T) { cpuprofile(100) }
func Test_cpuprofile200(t *testing.T) { cpuprofile(200) }

[qmuntal]

Thanks for the new reproducers @ypcd.

While working on CL 514375 I've noticed that the default cpu sampling rate (100Hz) is already too high on Windows, which has a timer frequency of 15.6ms (~64Hz). This was regressed in go1.16 due to #44343.

[ypcd]

Thanks for the new reproducers @ypcd.

While working on CL 514375 I've noticed that the default cpu sampling rate (100Hz) is already too high on Windows, which has a timer frequency of 15.6ms (~64Hz). This was regressed in go1.16 due to #44343.

Thank you for your reply.