goroutine.go

// Code from https://go.googlesource.com/proposal/+/refs/changes/08/219508/2/design/36821-perf-counter-pprof.md#5-empirical-evidence-on-the-accuracy-and-precision-of-pmu-profiles
// Modified to support fgprof in addition to the builtin CPU Profiler.
package main

import (
	"errors"
	"fmt"
	"log"
	"os"
	"runtime/pprof"
	"sync"
	_ "time"

	"github.com/felixge/fgprof"
)

var wg sync.WaitGroup

func f1() {
	defer wg.Done()

	var sum int
	for i := 0; i < 500000000; i++ {
		sum -= i / 2
		sum *= i
		sum /= i/3 + 1
		sum -= i / 4
	}

	fmt.Println(sum)
}

func f2() {
	defer wg.Done()

	var sum int
	for i := 0; i < 500000000; i++ {
		sum -= i / 2
		sum *= i
		sum /= i/3 + 1
		sum -= i / 4
	}

	fmt.Println(sum)
}

func f3() {
	defer wg.Done()

	var sum int
	for i := 0; i < 500000000; i++ {
		sum -= i / 2
		sum *= i
		sum /= i/3 + 1
		sum -= i / 4
	}

	fmt.Println(sum)
}

func f4() {
	defer wg.Done()

	var sum int
	for i := 0; i < 500000000; i++ {
		sum -= i / 2
		sum *= i
		sum /= i/3 + 1
		sum -= i / 4
	}

	fmt.Println(sum)
}

func f5() {
	defer wg.Done()

	var sum int
	for i := 0; i < 500000000; i++ {
		sum -= i / 2
		sum *= i
		sum /= i/3 + 1
		sum -= i / 4
	}

	fmt.Println(sum)
}

func f6() {
	defer wg.Done()

	var sum int
	for i := 0; i < 500000000; i++ {
		sum -= i / 2
		sum *= i
		sum /= i/3 + 1
		sum -= i / 4
	}

	fmt.Println(sum)
}

func f7() {
	defer wg.Done()

	var sum int
	for i := 0; i < 500000000; i++ {
		sum -= i / 2
		sum *= i
		sum /= i/3 + 1
		sum -= i / 4
	}

	fmt.Println(sum)
}

func f8() {
	defer wg.Done()

	var sum int
	for i := 0; i < 500000000; i++ {
		sum -= i / 2
		sum *= i
		sum /= i/3 + 1
		sum -= i / 4
	}

	fmt.Println(sum)
}

func f9() {
	defer wg.Done()

	var sum int
	for i := 0; i < 500000000; i++ {
		sum -= i / 2
		sum *= i
		sum /= i/3 + 1
		sum -= i / 4
	}

	fmt.Println(sum)
}

func f10() {
	defer wg.Done()

	var sum int
	for i := 0; i < 500000000; i++ {
		sum -= i / 2
		sum *= i
		sum /= i/3 + 1
		sum -= i / 4
	}

	fmt.Println(sum)
}

func run() error {
	badArgs := errors.New("usage: ./goroutine <builtin|fgprof> <filename>")
	if len(os.Args) != 3 {
		return badArgs
	}

	timerFile, err := os.Create(os.Args[2])
	if err != nil {
		return err
	}
	defer timerFile.Close()

	switch os.Args[1] {
	case "builtin":
		if err := pprof.StartCPUProfile(timerFile); err != nil {
			return err
		}

		defer pprof.StopCPUProfile()
	case "fgprof":
		stop := fgprof.Start(timerFile, fgprof.FormatPprof)
		defer stop()
	default:
		return fmt.Errorf("bad arg: %q: %w", os.Args[1], badArgs)
	}

	wg.Add(10)
	defer wg.Wait()

	go f1()
	go f2()
	go f3()
	go f4()
	go f5()
	go f6()
	go f7()
	go f8()
	go f9()
	go f10()

	return nil
}

func main() {
	if err := run(); err != nil {
		log.Fatal(err)
	}
}

usage.txt

$ go run goroutine.go fgprof fgprof.pprof
$ go run goroutine.go builtin builtin.pprof

# results on my i7 quadcore macbook pro on darwin
$ go tool pprof builtin.pprof 
Type: cpu
Time: Jun 25, 2020 at 5:43pm (CEST)
Duration: 11.46s, Total samples = 1.05mins (547.91%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 57.67s, 91.83% of 62.80s total
Dropped 17 nodes (cum <= 0.31s)
Showing top 10 nodes out of 11
      flat  flat%   sum%        cum   cum%
     5.99s  9.54%  9.54%      6.54s 10.41%  main.f2
     5.98s  9.52% 19.06%      6.54s 10.41%  main.f3
     5.88s  9.36% 28.42%      6.42s 10.22%  main.f6
     5.83s  9.28% 37.71%      6.32s 10.06%  main.f8
     5.77s  9.19% 46.89%      6.17s  9.82%  main.f5
     5.72s  9.11% 56.00%      6.23s  9.92%  main.f10
     5.70s  9.08% 65.08%      6.24s  9.94%  main.f4
     5.68s  9.04% 74.12%      6.09s  9.70%  main.f9
     5.65s  9.00% 83.12%      6.18s  9.84%  main.f7
     5.47s  8.71% 91.83%      6.03s  9.60%  main.f1
$ go tool pprof fgprof.pprof
Type: time
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 57.89s, 100% of 57.89s total
Showing top 10 nodes out of 20
      flat  flat%   sum%        cum   cum%
    52.45s 90.61% 90.61%     52.45s 90.61%  runtime.asyncPreempt2
     5.42s  9.37%   100%      5.42s  9.37%  runtime.gopark
     0.01s 0.017%   100%      5.41s  9.35%  main.f9
         0     0%   100%      5.32s  9.20%  main.f1
         0     0%   100%      5.20s  8.99%  main.f10
         0     0%   100%      5.26s  9.09%  main.f2
         0     0%   100%      5.03s  8.69%  main.f3
         0     0%   100%      5.37s  9.28%  main.f4
         0     0%   100%      5.17s  8.93%  main.f5
         0     0%   100%      5.16s  8.92%  main.f6