1
2
3
4
5
6
7 package pprof
8
9 import (
10 "bytes"
11 "context"
12 "fmt"
13 "internal/abi"
14 "internal/profile"
15 "internal/runtime/pprof/label"
16 "internal/syscall/unix"
17 "internal/testenv"
18 "io"
19 "iter"
20 "math"
21 "math/big"
22 "os"
23 "regexp"
24 "runtime"
25 "runtime/debug"
26 "slices"
27 "strconv"
28 "strings"
29 "sync"
30 "sync/atomic"
31 "testing"
32 "time"
33 _ "unsafe"
34 )
35
36 func cpuHogger(f func(x int) int, y *int, dur time.Duration) {
37
38
39
40
41
42 t0 := time.Now()
43 accum := *y
44 for i := 0; i < 500 || time.Since(t0) < dur; i++ {
45 accum = f(accum)
46 }
47 *y = accum
48 }
49
50 var (
51 salt1 = 0
52 salt2 = 0
53 )
54
55
56
57
58 func cpuHog1(x int) int {
59 return cpuHog0(x, 1e5)
60 }
61
62 func cpuHog0(x, n int) int {
63 foo := x
64 for i := 0; i < n; i++ {
65 if foo > 0 {
66 foo *= foo
67 } else {
68 foo *= foo + 1
69 }
70 }
71 return foo
72 }
73
74 func cpuHog2(x int) int {
75 foo := x
76 for i := 0; i < 1e5; i++ {
77 if foo > 0 {
78 foo *= foo
79 } else {
80 foo *= foo + 2
81 }
82 }
83 return foo
84 }
85
86
87
88 func avoidFunctions() []string {
89 if runtime.Compiler == "gccgo" {
90 return []string{"runtime.sigprof"}
91 }
92 return nil
93 }
94
95 func TestCPUProfile(t *testing.T) {
96 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions())
97 testCPUProfile(t, matches, func(dur time.Duration) {
98 cpuHogger(cpuHog1, &salt1, dur)
99 })
100 }
101
102 func TestCPUProfileMultithreaded(t *testing.T) {
103 defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2))
104 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1", "runtime/pprof.cpuHog2"}, avoidFunctions())
105 testCPUProfile(t, matches, func(dur time.Duration) {
106 c := make(chan int)
107 go func() {
108 cpuHogger(cpuHog1, &salt1, dur)
109 c <- 1
110 }()
111 cpuHogger(cpuHog2, &salt2, dur)
112 <-c
113 })
114 }
115
116 func TestCPUProfileMultithreadMagnitude(t *testing.T) {
117 if runtime.GOOS != "linux" {
118 t.Skip("issue 35057 is only confirmed on Linux")
119 }
120
121 defer func() {
122 if t.Failed() {
123 t.Logf("Failure of this test may indicate that your system suffers from a known Linux kernel bug fixed on newer kernels. See https://golang.org/issue/49065.")
124 }
125 }()
126
127
128
129
130 if testenv.Builder() != "" && (runtime.GOARCH == "386" || runtime.GOARCH == "amd64") {
131
132
133 if unix.KernelVersionGE(5, 9) && !unix.KernelVersionGE(5, 16) {
134 testenv.SkipFlaky(t, 49065)
135 }
136 }
137
138
139
140
141
142
143
144
145
146
147
148
149 maxDiff := 0.10
150 if testing.Short() {
151 maxDiff = 0.40
152 }
153
154 compare := func(a, b time.Duration, maxDiff float64) error {
155 if a <= 0 || b <= 0 {
156 return fmt.Errorf("Expected both time reports to be positive")
157 }
158
159 if a < b {
160 a, b = b, a
161 }
162
163 diff := float64(a-b) / float64(a)
164 if diff > maxDiff {
165 return fmt.Errorf("CPU usage reports are too different (limit -%.1f%%, got -%.1f%%)", maxDiff*100, diff*100)
166 }
167
168 return nil
169 }
170
171 for _, tc := range []struct {
172 name string
173 workers int
174 }{
175 {
176 name: "serial",
177 workers: 1,
178 },
179 {
180 name: "parallel",
181 workers: runtime.GOMAXPROCS(0),
182 },
183 } {
184
185 t.Run(tc.name, func(t *testing.T) {
186 t.Logf("Running with %d workers", tc.workers)
187
188 var userTime, systemTime time.Duration
189 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.cpuHog1"}, avoidFunctions())
190 acceptProfile := func(t *testing.T, p *profile.Profile) bool {
191 if !matches(t, p) {
192 return false
193 }
194
195 ok := true
196 for i, unit := range []string{"count", "nanoseconds"} {
197 if have, want := p.SampleType[i].Unit, unit; have != want {
198 t.Logf("pN SampleType[%d]; %q != %q", i, have, want)
199 ok = false
200 }
201 }
202
203
204
205
206
207
208 var value time.Duration
209 for _, sample := range p.Sample {
210 value += time.Duration(sample.Value[1]) * time.Nanosecond
211 }
212
213 totalTime := userTime + systemTime
214 t.Logf("compare %s user + %s system = %s vs %s", userTime, systemTime, totalTime, value)
215 if err := compare(totalTime, value, maxDiff); err != nil {
216 t.Logf("compare got %v want nil", err)
217 ok = false
218 }
219
220 return ok
221 }
222
223 testCPUProfile(t, acceptProfile, func(dur time.Duration) {
224 userTime, systemTime = diffCPUTime(t, func() {
225 var wg sync.WaitGroup
226 var once sync.Once
227 for i := 0; i < tc.workers; i++ {
228 wg.Add(1)
229 go func() {
230 defer wg.Done()
231 var salt = 0
232 cpuHogger(cpuHog1, &salt, dur)
233 once.Do(func() { salt1 = salt })
234 }()
235 }
236 wg.Wait()
237 })
238 })
239 })
240 }
241 }
242
243
244
245 func containsInlinedCall(f any, maxBytes int) bool {
246 _, found := findInlinedCall(f, maxBytes)
247 return found
248 }
249
250
251
252 func findInlinedCall(f any, maxBytes int) (pc uint64, found bool) {
253 fFunc := runtime.FuncForPC(uintptr(abi.FuncPCABIInternal(f)))
254 if fFunc == nil || fFunc.Entry() == 0 {
255 panic("failed to locate function entry")
256 }
257
258 for offset := 0; offset < maxBytes; offset++ {
259 innerPC := fFunc.Entry() + uintptr(offset)
260 inner := runtime.FuncForPC(innerPC)
261 if inner == nil {
262
263
264 continue
265 }
266 if inner.Entry() != fFunc.Entry() {
267
268 break
269 }
270 if inner.Name() != fFunc.Name() {
271
272
273 return uint64(innerPC), true
274 }
275 }
276
277 return 0, false
278 }
279
280 func TestCPUProfileInlining(t *testing.T) {
281 if !containsInlinedCall(inlinedCaller, 4<<10) {
282 t.Skip("Can't determine whether inlinedCallee was inlined into inlinedCaller.")
283 }
284
285 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.inlinedCaller"}, avoidFunctions())
286 p := testCPUProfile(t, matches, func(dur time.Duration) {
287 cpuHogger(inlinedCaller, &salt1, dur)
288 })
289
290
291 for _, loc := range p.Location {
292 hasInlinedCallerAfterInlinedCallee, hasInlinedCallee := false, false
293 for _, line := range loc.Line {
294 if line.Function.Name == "runtime/pprof.inlinedCallee" {
295 hasInlinedCallee = true
296 }
297 if hasInlinedCallee && line.Function.Name == "runtime/pprof.inlinedCaller" {
298 hasInlinedCallerAfterInlinedCallee = true
299 }
300 }
301 if hasInlinedCallee != hasInlinedCallerAfterInlinedCallee {
302 t.Fatalf("want inlinedCallee followed by inlinedCaller, got separate Location entries:\n%v", p)
303 }
304 }
305 }
306
307 func inlinedCaller(x int) int {
308 x = inlinedCallee(x, 1e5)
309 return x
310 }
311
312 func inlinedCallee(x, n int) int {
313 return cpuHog0(x, n)
314 }
315
316
317 func dumpCallers(pcs []uintptr) {
318 if pcs == nil {
319 return
320 }
321
322 skip := 2
323 runtime.Callers(skip, pcs)
324 }
325
326
327 func inlinedCallerDump(pcs []uintptr) {
328 inlinedCalleeDump(pcs)
329 }
330
331 func inlinedCalleeDump(pcs []uintptr) {
332 dumpCallers(pcs)
333 }
334
335 type inlineWrapperInterface interface {
336 dump(stack []uintptr)
337 }
338
339 type inlineWrapper struct {
340 }
341
342 func (h inlineWrapper) dump(pcs []uintptr) {
343 dumpCallers(pcs)
344 }
345
346 func inlinedWrapperCallerDump(pcs []uintptr) {
347 var h inlineWrapperInterface
348
349
350
351 _ = &h
352
353 h = &inlineWrapper{}
354 h.dump(pcs)
355 }
356
357 func TestCPUProfileRecursion(t *testing.T) {
358 matches := matchAndAvoidStacks(stackContains, []string{"runtime/pprof.inlinedCallee", "runtime/pprof.recursionCallee", "runtime/pprof.recursionCaller"}, avoidFunctions())
359 p := testCPUProfile(t, matches, func(dur time.Duration) {
360 cpuHogger(recursionCaller, &salt1, dur)
361 })
362
363
364 for i, loc := range p.Location {
365 recursionFunc := 0
366 for _, line := range loc.Line {
367 if name := line.Function.Name; name == "runtime/pprof.recursionCaller" || name == "runtime/pprof.recursionCallee" {
368 recursionFunc++
369 }
370 }
371 if recursionFunc > 1 {
372 t.Fatalf("want at most one recursionCaller or recursionCallee in one Location, got a violating Location (index: %d):\n%v", i, p)
373 }
374 }
375 }
376
377 func recursionCaller(x int) int {
378 y := recursionCallee(3, x)
379 return y
380 }
381
382 func recursionCallee(n, x int) int {
383 if n == 0 {
384 return 1
385 }
386 y := inlinedCallee(x, 1e4)
387 return y * recursionCallee(n-1, x)
388 }
389
390 func recursionChainTop(x int, pcs []uintptr) {
391 if x < 0 {
392 return
393 }
394 recursionChainMiddle(x, pcs)
395 }
396
397 func recursionChainMiddle(x int, pcs []uintptr) {
398 recursionChainBottom(x, pcs)
399 }
400
401 func recursionChainBottom(x int, pcs []uintptr) {
402
403
404 dumpCallers(pcs)
405
406 recursionChainTop(x-1, pcs)
407 }
408
409 func parseProfile(t *testing.T, valBytes []byte, f func(uintptr, []*profile.Location, map[string][]string)) *profile.Profile {
410 p, err := profile.Parse(bytes.NewReader(valBytes))
411 if err != nil {
412 t.Fatal(err)
413 }
414 for _, sample := range p.Sample {
415 count := uintptr(sample.Value[0])
416 f(count, sample.Location, sample.Label)
417 }
418 return p
419 }
420
421
422
423 func testCPUProfile(t *testing.T, matches profileMatchFunc, f func(dur time.Duration)) *profile.Profile {
424 switch runtime.GOOS {
425 case "darwin":
426 out, err := testenv.Command(t, "uname", "-a").CombinedOutput()
427 if err != nil {
428 t.Fatal(err)
429 }
430 vers := string(out)
431 t.Logf("uname -a: %v", vers)
432 case "plan9":
433 t.Skip("skipping on plan9")
434 case "wasip1":
435 t.Skip("skipping on wasip1")
436 }
437
438 broken := testenv.CPUProfilingBroken()
439
440 deadline, ok := t.Deadline()
441 if broken || !ok {
442 if broken && testing.Short() {
443
444 deadline = time.Now().Add(1 * time.Second)
445 } else {
446 deadline = time.Now().Add(10 * time.Second)
447 }
448 }
449
450
451
452 duration := 5 * time.Second
453 if testing.Short() {
454 duration = 100 * time.Millisecond
455 }
456
457
458
459
460
461
462 for {
463 var prof bytes.Buffer
464 if err := StartCPUProfile(&prof); err != nil {
465 t.Fatal(err)
466 }
467 f(duration)
468 StopCPUProfile()
469
470 if p, ok := profileOk(t, matches, &prof, duration); ok {
471 return p
472 }
473
474 duration *= 2
475 if time.Until(deadline) < duration {
476 break
477 }
478 t.Logf("retrying with %s duration", duration)
479 }
480
481 if broken {
482 t.Skipf("ignoring failure on %s/%s; see golang.org/issue/13841", runtime.GOOS, runtime.GOARCH)
483 }
484
485
486
487
488
489 if os.Getenv("IN_QEMU") == "1" {
490 t.Skip("ignore the failure in QEMU; see golang.org/issue/9605")
491 }
492 t.FailNow()
493 return nil
494 }
495
496 var diffCPUTimeImpl func(f func()) (user, system time.Duration)
497
498 func diffCPUTime(t *testing.T, f func()) (user, system time.Duration) {
499 if fn := diffCPUTimeImpl; fn != nil {
500 return fn(f)
501 }
502 t.Fatalf("cannot measure CPU time on GOOS=%s GOARCH=%s", runtime.GOOS, runtime.GOARCH)
503 return 0, 0
504 }
505
506
507 func stackContains(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
508 for _, loc := range stk {
509 for _, line := range loc.Line {
510 if strings.Contains(line.Function.Name, spec) {
511 return true
512 }
513 }
514 }
515 return false
516 }
517
518 type sampleMatchFunc func(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool
519
520 func profileOk(t *testing.T, matches profileMatchFunc, prof *bytes.Buffer, duration time.Duration) (_ *profile.Profile, ok bool) {
521 ok = true
522
523 var samples uintptr
524 var buf strings.Builder
525 p := parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, labels map[string][]string) {
526 fmt.Fprintf(&buf, "%d:", count)
527 fprintStack(&buf, stk)
528 fmt.Fprintf(&buf, " labels: %v\n", labels)
529 samples += count
530 fmt.Fprintf(&buf, "\n")
531 })
532 t.Logf("total %d CPU profile samples collected:\n%s", samples, buf.String())
533
534 if samples < 10 && runtime.GOOS == "windows" {
535
536
537
538 t.Log("too few samples on Windows (golang.org/issue/10842)")
539 return p, false
540 }
541
542
543
544
545
546
547 if ideal := uintptr(duration * 100 / time.Second); samples == 0 || (samples < ideal/4 && samples < 10) {
548 t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal)
549 ok = false
550 }
551
552 if matches != nil && !matches(t, p) {
553 ok = false
554 }
555
556 return p, ok
557 }
558
559 type profileMatchFunc func(*testing.T, *profile.Profile) bool
560
561 func matchAndAvoidStacks(matches sampleMatchFunc, need []string, avoid []string) profileMatchFunc {
562 return func(t *testing.T, p *profile.Profile) (ok bool) {
563 ok = true
564
565
566
567 have := make([]uintptr, len(need))
568 avoidSamples := make([]uintptr, len(avoid))
569
570 for _, sample := range p.Sample {
571 count := uintptr(sample.Value[0])
572 for i, spec := range need {
573 if matches(spec, count, sample.Location, sample.Label) {
574 have[i] += count
575 }
576 }
577 for i, name := range avoid {
578 for _, loc := range sample.Location {
579 for _, line := range loc.Line {
580 if strings.Contains(line.Function.Name, name) {
581 avoidSamples[i] += count
582 }
583 }
584 }
585 }
586 }
587
588 for i, name := range avoid {
589 bad := avoidSamples[i]
590 if bad != 0 {
591 t.Logf("found %d samples in avoid-function %s\n", bad, name)
592 ok = false
593 }
594 }
595
596 if len(need) == 0 {
597 return
598 }
599
600 var total uintptr
601 for i, name := range need {
602 total += have[i]
603 t.Logf("found %d samples in expected function %s\n", have[i], name)
604 }
605 if total == 0 {
606 t.Logf("no samples in expected functions")
607 ok = false
608 }
609
610
611
612
613
614 min := uintptr(1)
615 for i, name := range need {
616 if have[i] < min {
617 t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have)))
618 ok = false
619 }
620 }
621 return
622 }
623 }
624
625
626
627 func TestCPUProfileWithFork(t *testing.T) {
628 testenv.MustHaveExec(t)
629
630 exe, err := os.Executable()
631 if err != nil {
632 t.Fatal(err)
633 }
634
635 heap := 1 << 30
636 if runtime.GOOS == "android" {
637
638 heap = 100 << 20
639 }
640 if testing.Short() {
641 heap = 100 << 20
642 }
643
644 garbage := make([]byte, heap)
645
646 done := make(chan bool)
647 go func() {
648 for i := range garbage {
649 garbage[i] = 42
650 }
651 done <- true
652 }()
653 <-done
654
655 var prof bytes.Buffer
656 if err := StartCPUProfile(&prof); err != nil {
657 t.Fatal(err)
658 }
659 defer StopCPUProfile()
660
661 for i := 0; i < 10; i++ {
662 testenv.Command(t, exe, "-h").CombinedOutput()
663 }
664 }
665
666
667
668
669 func TestGoroutineSwitch(t *testing.T) {
670 if runtime.Compiler == "gccgo" {
671 t.Skip("not applicable for gccgo")
672 }
673
674
675
676 tries := 10
677 count := 1000000
678 if testing.Short() {
679 tries = 1
680 }
681 for try := 0; try < tries; try++ {
682 var prof bytes.Buffer
683 if err := StartCPUProfile(&prof); err != nil {
684 t.Fatal(err)
685 }
686 for i := 0; i < count; i++ {
687 runtime.Gosched()
688 }
689 StopCPUProfile()
690
691
692
693
694
695 parseProfile(t, prof.Bytes(), func(count uintptr, stk []*profile.Location, _ map[string][]string) {
696
697
698 if len(stk) == 2 {
699 name := stk[1].Line[0].Function.Name
700 if name == "runtime._System" || name == "runtime._ExternalCode" || name == "runtime._GC" {
701 return
702 }
703 }
704
705
706
707 if len(stk) == 1 {
708 return
709 }
710
711
712
713 name := stk[0].Line[0].Function.Name
714 if name == "gogo" {
715 var buf strings.Builder
716 fprintStack(&buf, stk)
717 t.Fatalf("found profile entry for gogo:\n%s", buf.String())
718 }
719 })
720 }
721 }
722
723 func fprintStack(w io.Writer, stk []*profile.Location) {
724 if len(stk) == 0 {
725 fmt.Fprintf(w, " (stack empty)")
726 }
727 for _, loc := range stk {
728 fmt.Fprintf(w, " %#x", loc.Address)
729 fmt.Fprintf(w, " (")
730 for i, line := range loc.Line {
731 if i > 0 {
732 fmt.Fprintf(w, " ")
733 }
734 fmt.Fprintf(w, "%s:%d", line.Function.Name, line.Line)
735 }
736 fmt.Fprintf(w, ")")
737 }
738 }
739
740
741 func TestMathBigDivide(t *testing.T) {
742 testCPUProfile(t, nil, func(duration time.Duration) {
743 t := time.After(duration)
744 pi := new(big.Int)
745 for {
746 for i := 0; i < 100; i++ {
747 n := big.NewInt(2646693125139304345)
748 d := big.NewInt(842468587426513207)
749 pi.Div(n, d)
750 }
751 select {
752 case <-t:
753 return
754 default:
755 }
756 }
757 })
758 }
759
760
761 func stackContainsAll(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
762 for _, f := range strings.Split(spec, ",") {
763 if !stackContains(f, count, stk, labels) {
764 return false
765 }
766 }
767 return true
768 }
769
770 func TestMorestack(t *testing.T) {
771 matches := matchAndAvoidStacks(stackContainsAll, []string{"runtime.newstack,runtime/pprof.growstack"}, avoidFunctions())
772 testCPUProfile(t, matches, func(duration time.Duration) {
773 t := time.After(duration)
774 c := make(chan bool)
775 for {
776 go func() {
777 growstack1()
778
779 select {
780 case c <- true:
781 case <-time.After(duration):
782 }
783 }()
784 select {
785 case <-t:
786 return
787 case <-c:
788 }
789 }
790 })
791 }
792
793
794 func growstack1() {
795 growstack(10)
796 }
797
798
799 func growstack(n int) {
800 var buf [8 << 18]byte
801 use(buf)
802 if n > 0 {
803 growstack(n - 1)
804 }
805 }
806
807
808 func use(x [8 << 18]byte) {}
809
810 func TestBlockProfile(t *testing.T) {
811 type TestCase struct {
812 name string
813 f func(*testing.T)
814 stk []string
815 re string
816 }
817 tests := [...]TestCase{
818 {
819 name: "chan recv",
820 f: blockChanRecv,
821 stk: []string{
822 "runtime.chanrecv1",
823 "runtime/pprof.blockChanRecv",
824 "runtime/pprof.TestBlockProfile",
825 },
826 re: `
827 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
828 # 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*runtime/chan.go:[0-9]+
829 # 0x[0-9a-f]+ runtime/pprof\.blockChanRecv\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
830 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
831 `},
832 {
833 name: "chan send",
834 f: blockChanSend,
835 stk: []string{
836 "runtime.chansend1",
837 "runtime/pprof.blockChanSend",
838 "runtime/pprof.TestBlockProfile",
839 },
840 re: `
841 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
842 # 0x[0-9a-f]+ runtime\.chansend1\+0x[0-9a-f]+ .*runtime/chan.go:[0-9]+
843 # 0x[0-9a-f]+ runtime/pprof\.blockChanSend\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
844 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
845 `},
846 {
847 name: "chan close",
848 f: blockChanClose,
849 stk: []string{
850 "runtime.chanrecv1",
851 "runtime/pprof.blockChanClose",
852 "runtime/pprof.TestBlockProfile",
853 },
854 re: `
855 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
856 # 0x[0-9a-f]+ runtime\.chanrecv1\+0x[0-9a-f]+ .*runtime/chan.go:[0-9]+
857 # 0x[0-9a-f]+ runtime/pprof\.blockChanClose\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
858 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
859 `},
860 {
861 name: "select recv async",
862 f: blockSelectRecvAsync,
863 stk: []string{
864 "runtime.selectgo",
865 "runtime/pprof.blockSelectRecvAsync",
866 "runtime/pprof.TestBlockProfile",
867 },
868 re: `
869 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
870 # 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*runtime/select.go:[0-9]+
871 # 0x[0-9a-f]+ runtime/pprof\.blockSelectRecvAsync\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
872 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
873 `},
874 {
875 name: "select send sync",
876 f: blockSelectSendSync,
877 stk: []string{
878 "runtime.selectgo",
879 "runtime/pprof.blockSelectSendSync",
880 "runtime/pprof.TestBlockProfile",
881 },
882 re: `
883 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
884 # 0x[0-9a-f]+ runtime\.selectgo\+0x[0-9a-f]+ .*runtime/select.go:[0-9]+
885 # 0x[0-9a-f]+ runtime/pprof\.blockSelectSendSync\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
886 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
887 `},
888 {
889 name: "mutex",
890 f: blockMutex,
891 stk: []string{
892 "sync.(*Mutex).Lock",
893 "runtime/pprof.blockMutex",
894 "runtime/pprof.TestBlockProfile",
895 },
896 re: `
897 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
898 # 0x[0-9a-f]+ sync\.\(\*Mutex\)\.Lock\+0x[0-9a-f]+ .*sync/mutex\.go:[0-9]+
899 # 0x[0-9a-f]+ runtime/pprof\.blockMutex\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
900 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
901 `},
902 {
903 name: "cond",
904 f: blockCond,
905 stk: []string{
906 "sync.(*Cond).Wait",
907 "runtime/pprof.blockCond",
908 "runtime/pprof.TestBlockProfile",
909 },
910 re: `
911 [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
912 # 0x[0-9a-f]+ sync\.\(\*Cond\)\.Wait\+0x[0-9a-f]+ .*sync/cond\.go:[0-9]+
913 # 0x[0-9a-f]+ runtime/pprof\.blockCond\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
914 # 0x[0-9a-f]+ runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+ .*runtime/pprof/pprof_test.go:[0-9]+
915 `},
916 }
917
918
919 runtime.SetBlockProfileRate(1)
920 defer runtime.SetBlockProfileRate(0)
921 for _, test := range tests {
922 test.f(t)
923 }
924
925 t.Run("debug=1", func(t *testing.T) {
926 var w strings.Builder
927 Lookup("block").WriteTo(&w, 1)
928 prof := w.String()
929
930 if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") {
931 t.Fatalf("Bad profile header:\n%v", prof)
932 }
933
934 if strings.HasSuffix(prof, "#\t0x0\n\n") {
935 t.Errorf("Useless 0 suffix:\n%v", prof)
936 }
937
938 for _, test := range tests {
939 if !regexp.MustCompile(strings.ReplaceAll(test.re, "\t", "\t+")).MatchString(prof) {
940 t.Errorf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof)
941 }
942 }
943 })
944
945 t.Run("proto", func(t *testing.T) {
946
947 var w bytes.Buffer
948 Lookup("block").WriteTo(&w, 0)
949 p, err := profile.Parse(&w)
950 if err != nil {
951 t.Fatalf("failed to parse profile: %v", err)
952 }
953 t.Logf("parsed proto: %s", p)
954 if err := p.CheckValid(); err != nil {
955 t.Fatalf("invalid profile: %v", err)
956 }
957
958 stks := profileStacks(p)
959 for _, test := range tests {
960 if !containsStack(stks, test.stk) {
961 t.Errorf("No matching stack entry for %v, want %+v", test.name, test.stk)
962 }
963 }
964 })
965
966 }
967
968 func profileStacks(p *profile.Profile) (res [][]string) {
969 for _, s := range p.Sample {
970 var stk []string
971 for _, l := range s.Location {
972 for _, line := range l.Line {
973 stk = append(stk, line.Function.Name)
974 }
975 }
976 res = append(res, stk)
977 }
978 return res
979 }
980
981 func blockRecordStacks(records []runtime.BlockProfileRecord) (res [][]string) {
982 for _, record := range records {
983 frames := runtime.CallersFrames(record.Stack())
984 var stk []string
985 for {
986 frame, more := frames.Next()
987 stk = append(stk, frame.Function)
988 if !more {
989 break
990 }
991 }
992 res = append(res, stk)
993 }
994 return res
995 }
996
997 func containsStack(got [][]string, want []string) bool {
998 for _, stk := range got {
999 if len(stk) < len(want) {
1000 continue
1001 }
1002 for i, f := range want {
1003 if f != stk[i] {
1004 break
1005 }
1006 if i == len(want)-1 {
1007 return true
1008 }
1009 }
1010 }
1011 return false
1012 }
1013
1014
1015
1016
1017 func awaitBlockedGoroutine(t *testing.T, state, fName string, count int) {
1018 re := fmt.Sprintf(`(?m)^goroutine \d+ \[%s\]:\n(?:.+\n\t.+\n)*runtime/pprof\.%s`, regexp.QuoteMeta(state), fName)
1019 r := regexp.MustCompile(re)
1020
1021 if deadline, ok := t.Deadline(); ok {
1022 if d := time.Until(deadline); d > 1*time.Second {
1023 timer := time.AfterFunc(d-1*time.Second, func() {
1024 debug.SetTraceback("all")
1025 panic(fmt.Sprintf("timed out waiting for %#q", re))
1026 })
1027 defer timer.Stop()
1028 }
1029 }
1030
1031 buf := make([]byte, 64<<10)
1032 for {
1033 runtime.Gosched()
1034 n := runtime.Stack(buf, true)
1035 if n == len(buf) {
1036
1037
1038 buf = make([]byte, 2*len(buf))
1039 continue
1040 }
1041 if len(r.FindAll(buf[:n], -1)) >= count {
1042 return
1043 }
1044 }
1045 }
1046
1047 func blockChanRecv(t *testing.T) {
1048 c := make(chan bool)
1049 go func() {
1050 awaitBlockedGoroutine(t, "chan receive", "blockChanRecv", 1)
1051 c <- true
1052 }()
1053 <-c
1054 }
1055
1056 func blockChanSend(t *testing.T) {
1057 c := make(chan bool)
1058 go func() {
1059 awaitBlockedGoroutine(t, "chan send", "blockChanSend", 1)
1060 <-c
1061 }()
1062 c <- true
1063 }
1064
1065 func blockChanClose(t *testing.T) {
1066 c := make(chan bool)
1067 go func() {
1068 awaitBlockedGoroutine(t, "chan receive", "blockChanClose", 1)
1069 close(c)
1070 }()
1071 <-c
1072 }
1073
1074 func blockSelectRecvAsync(t *testing.T) {
1075 const numTries = 3
1076 c := make(chan bool, 1)
1077 c2 := make(chan bool, 1)
1078 go func() {
1079 for i := 0; i < numTries; i++ {
1080 awaitBlockedGoroutine(t, "select", "blockSelectRecvAsync", 1)
1081 c <- true
1082 }
1083 }()
1084 for i := 0; i < numTries; i++ {
1085 select {
1086 case <-c:
1087 case <-c2:
1088 }
1089 }
1090 }
1091
1092 func blockSelectSendSync(t *testing.T) {
1093 c := make(chan bool)
1094 c2 := make(chan bool)
1095 go func() {
1096 awaitBlockedGoroutine(t, "select", "blockSelectSendSync", 1)
1097 <-c
1098 }()
1099 select {
1100 case c <- true:
1101 case c2 <- true:
1102 }
1103 }
1104
1105 func blockMutex(t *testing.T) {
1106 var mu sync.Mutex
1107 mu.Lock()
1108 go func() {
1109 awaitBlockedGoroutine(t, "sync.Mutex.Lock", "blockMutex", 1)
1110 mu.Unlock()
1111 }()
1112
1113
1114
1115
1116 mu.Lock()
1117 }
1118
1119 func blockMutexN(t *testing.T, n int, d time.Duration) {
1120 var wg sync.WaitGroup
1121 var mu sync.Mutex
1122 mu.Lock()
1123 go func() {
1124 awaitBlockedGoroutine(t, "sync.Mutex.Lock", "blockMutex", n)
1125 time.Sleep(d)
1126 mu.Unlock()
1127 }()
1128
1129
1130
1131
1132 for i := 0; i < n; i++ {
1133 wg.Add(1)
1134 go func() {
1135 defer wg.Done()
1136 mu.Lock()
1137 mu.Unlock()
1138 }()
1139 }
1140 wg.Wait()
1141 }
1142
1143 func blockCond(t *testing.T) {
1144 var mu sync.Mutex
1145 c := sync.NewCond(&mu)
1146 mu.Lock()
1147 go func() {
1148 awaitBlockedGoroutine(t, "sync.Cond.Wait", "blockCond", 1)
1149 mu.Lock()
1150 c.Signal()
1151 mu.Unlock()
1152 }()
1153 c.Wait()
1154 mu.Unlock()
1155 }
1156
1157
1158 func TestBlockProfileBias(t *testing.T) {
1159 rate := int(1000)
1160 runtime.SetBlockProfileRate(rate)
1161 defer runtime.SetBlockProfileRate(0)
1162
1163
1164 blockFrequentShort(rate)
1165 blockInfrequentLong(rate)
1166
1167 var w bytes.Buffer
1168 Lookup("block").WriteTo(&w, 0)
1169 p, err := profile.Parse(&w)
1170 if err != nil {
1171 t.Fatalf("failed to parse profile: %v", err)
1172 }
1173 t.Logf("parsed proto: %s", p)
1174
1175 il := float64(-1)
1176 fs := float64(-1)
1177 for _, s := range p.Sample {
1178 for _, l := range s.Location {
1179 for _, line := range l.Line {
1180 if len(s.Value) < 2 {
1181 t.Fatal("block profile has less than 2 sample types")
1182 }
1183
1184 if line.Function.Name == "runtime/pprof.blockInfrequentLong" {
1185 il = float64(s.Value[1])
1186 } else if line.Function.Name == "runtime/pprof.blockFrequentShort" {
1187 fs = float64(s.Value[1])
1188 }
1189 }
1190 }
1191 }
1192 if il == -1 || fs == -1 {
1193 t.Fatal("block profile is missing expected functions")
1194 }
1195
1196
1197 const threshold = 0.2
1198 if bias := (il - fs) / il; math.Abs(bias) > threshold {
1199 t.Fatalf("bias: abs(%f) > %f", bias, threshold)
1200 } else {
1201 t.Logf("bias: abs(%f) < %f", bias, threshold)
1202 }
1203 }
1204
1205
1206
1207 func blockFrequentShort(rate int) {
1208 for i := 0; i < 100000; i++ {
1209 blockevent(int64(rate/10), 1)
1210 }
1211 }
1212
1213
1214
1215 func blockInfrequentLong(rate int) {
1216 for i := 0; i < 10000; i++ {
1217 blockevent(int64(rate), 1)
1218 }
1219 }
1220
1221
1222
1223
1224 func blockevent(cycles int64, skip int)
1225
1226 func TestMutexProfile(t *testing.T) {
1227
1228
1229 old := runtime.SetMutexProfileFraction(1)
1230 defer runtime.SetMutexProfileFraction(old)
1231 if old != 0 {
1232 t.Fatalf("need MutexProfileRate 0, got %d", old)
1233 }
1234
1235 const (
1236 N = 100
1237 D = 100 * time.Millisecond
1238 )
1239 start := time.Now()
1240 blockMutexN(t, N, D)
1241 blockMutexNTime := time.Since(start)
1242
1243 t.Run("debug=1", func(t *testing.T) {
1244 var w strings.Builder
1245 Lookup("mutex").WriteTo(&w, 1)
1246 prof := w.String()
1247 t.Logf("received profile: %v", prof)
1248
1249 if !strings.HasPrefix(prof, "--- mutex:\ncycles/second=") {
1250 t.Errorf("Bad profile header:\n%v", prof)
1251 }
1252 prof = strings.Trim(prof, "\n")
1253 lines := strings.Split(prof, "\n")
1254 if len(lines) < 6 {
1255 t.Fatalf("expected >=6 lines, got %d %q\n%s", len(lines), prof, prof)
1256 }
1257
1258 r2 := `^\d+ \d+ @(?: 0x[[:xdigit:]]+)+`
1259 if ok, err := regexp.MatchString(r2, lines[3]); err != nil || !ok {
1260 t.Errorf("%q didn't match %q", lines[3], r2)
1261 }
1262 r3 := "^#.*runtime/pprof.blockMutex.*$"
1263 if ok, err := regexp.MatchString(r3, lines[5]); err != nil || !ok {
1264 t.Errorf("%q didn't match %q", lines[5], r3)
1265 }
1266 t.Log(prof)
1267 })
1268 t.Run("proto", func(t *testing.T) {
1269
1270 var w bytes.Buffer
1271 Lookup("mutex").WriteTo(&w, 0)
1272 p, err := profile.Parse(&w)
1273 if err != nil {
1274 t.Fatalf("failed to parse profile: %v", err)
1275 }
1276 t.Logf("parsed proto: %s", p)
1277 if err := p.CheckValid(); err != nil {
1278 t.Fatalf("invalid profile: %v", err)
1279 }
1280
1281 stks := profileStacks(p)
1282 for _, want := range [][]string{
1283 {"sync.(*Mutex).Unlock", "runtime/pprof.blockMutexN.func1"},
1284 } {
1285 if !containsStack(stks, want) {
1286 t.Errorf("No matching stack entry for %+v", want)
1287 }
1288 }
1289
1290 i := 0
1291 for ; i < len(p.SampleType); i++ {
1292 if p.SampleType[i].Unit == "nanoseconds" {
1293 break
1294 }
1295 }
1296 if i >= len(p.SampleType) {
1297 t.Fatalf("profile did not contain nanoseconds sample")
1298 }
1299 total := int64(0)
1300 for _, s := range p.Sample {
1301 total += s.Value[i]
1302 }
1303
1304
1305
1306
1307
1308
1309
1310
1311 d := time.Duration(total)
1312 lo := time.Duration(N * D * 9 / 10)
1313 hi := time.Duration(N) * blockMutexNTime * 11 / 10
1314 if d < lo || d > hi {
1315 for _, s := range p.Sample {
1316 t.Logf("sample: %s", time.Duration(s.Value[i]))
1317 }
1318 t.Fatalf("profile samples total %v, want within range [%v, %v] (target: %v)", d, lo, hi, N*D)
1319 }
1320 })
1321
1322 t.Run("records", func(t *testing.T) {
1323
1324 var records []runtime.BlockProfileRecord
1325 for {
1326 n, ok := runtime.MutexProfile(records)
1327 if ok {
1328 records = records[:n]
1329 break
1330 }
1331 records = make([]runtime.BlockProfileRecord, n*2)
1332 }
1333
1334
1335
1336
1337 stks := blockRecordStacks(records)
1338 want := []string{"sync.(*Mutex).Unlock", "runtime/pprof.blockMutexN.func1", "runtime.goexit"}
1339 if !containsStack(stks, want) {
1340 t.Errorf("No matching stack entry for %+v", want)
1341 }
1342 })
1343 }
1344
1345 func TestMutexProfileRateAdjust(t *testing.T) {
1346 old := runtime.SetMutexProfileFraction(1)
1347 defer runtime.SetMutexProfileFraction(old)
1348 if old != 0 {
1349 t.Fatalf("need MutexProfileRate 0, got %d", old)
1350 }
1351
1352 readProfile := func() (contentions int64, delay int64) {
1353 var w bytes.Buffer
1354 Lookup("mutex").WriteTo(&w, 0)
1355 p, err := profile.Parse(&w)
1356 if err != nil {
1357 t.Fatalf("failed to parse profile: %v", err)
1358 }
1359 t.Logf("parsed proto: %s", p)
1360 if err := p.CheckValid(); err != nil {
1361 t.Fatalf("invalid profile: %v", err)
1362 }
1363
1364 for _, s := range p.Sample {
1365 var match, runtimeInternal bool
1366 for _, l := range s.Location {
1367 for _, line := range l.Line {
1368 if line.Function.Name == "runtime/pprof.blockMutex.func1" {
1369 match = true
1370 }
1371 if line.Function.Name == "runtime.unlock" {
1372 runtimeInternal = true
1373 }
1374 }
1375 }
1376 if match && !runtimeInternal {
1377 contentions += s.Value[0]
1378 delay += s.Value[1]
1379 }
1380 }
1381 return
1382 }
1383
1384 blockMutex(t)
1385 contentions, delay := readProfile()
1386 if contentions == 0 {
1387 t.Fatal("did not see expected function in profile")
1388 }
1389 runtime.SetMutexProfileFraction(0)
1390 newContentions, newDelay := readProfile()
1391 if newContentions != contentions || newDelay != delay {
1392 t.Fatalf("sample value changed: got [%d, %d], want [%d, %d]", newContentions, newDelay, contentions, delay)
1393 }
1394 }
1395
1396 func func1(c chan int) { <-c }
1397 func func2(c chan int) { <-c }
1398 func func3(c chan int) { <-c }
1399 func func4(c chan int) { <-c }
1400
1401 func TestGoroutineCounts(t *testing.T) {
1402
1403
1404 defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
1405
1406 c := make(chan int)
1407 for i := 0; i < 100; i++ {
1408 switch {
1409 case i%10 == 0:
1410 go func1(c)
1411 case i%2 == 0:
1412 go func2(c)
1413 default:
1414 go func3(c)
1415 }
1416
1417 for j := 0; j < 5; j++ {
1418 runtime.Gosched()
1419 }
1420 }
1421 ctx := context.Background()
1422
1423
1424
1425 Do(ctx, Labels("label", "value"), func(context.Context) {
1426 for i := 0; i < 89; i++ {
1427 switch {
1428 case i%10 == 0:
1429 go func1(c)
1430 case i%2 == 0:
1431 go func2(c)
1432 default:
1433 go func3(c)
1434 }
1435
1436 for j := 0; j < 5; j++ {
1437 runtime.Gosched()
1438 }
1439 }
1440 })
1441
1442 SetGoroutineLabels(WithLabels(context.Background(), Labels("self-label", "self-value")))
1443 defer SetGoroutineLabels(context.Background())
1444
1445 garbage := new(*int)
1446 fingReady := make(chan struct{})
1447 runtime.SetFinalizer(garbage, func(v **int) {
1448 Do(context.Background(), Labels("fing-label", "fing-value"), func(ctx context.Context) {
1449 close(fingReady)
1450 <-c
1451 })
1452 })
1453 garbage = nil
1454 for i := 0; i < 2; i++ {
1455 runtime.GC()
1456 }
1457 <-fingReady
1458
1459 var w bytes.Buffer
1460 goroutineProf := Lookup("goroutine")
1461
1462
1463 goroutineProf.WriteTo(&w, 1)
1464 prof := w.String()
1465
1466 labels := labelMap{label.NewSet(Labels("label", "value").list)}
1467 labelStr := "\n# labels: " + labels.String()
1468 selfLabel := labelMap{label.NewSet(Labels("self-label", "self-value").list)}
1469 selfLabelStr := "\n# labels: " + selfLabel.String()
1470 fingLabel := labelMap{label.NewSet(Labels("fing-label", "fing-value").list)}
1471 fingLabelStr := "\n# labels: " + fingLabel.String()
1472 orderedPrefix := []string{
1473 "\n50 @ ",
1474 "\n44 @", labelStr,
1475 "\n40 @",
1476 "\n36 @", labelStr,
1477 "\n10 @",
1478 "\n9 @", labelStr,
1479 "\n1 @"}
1480 if !containsInOrder(prof, append(orderedPrefix, selfLabelStr)...) {
1481 t.Errorf("expected sorted goroutine counts with Labels:\n%s", prof)
1482 }
1483 if !containsInOrder(prof, append(orderedPrefix, fingLabelStr)...) {
1484 t.Errorf("expected sorted goroutine counts with Labels:\n%s", prof)
1485 }
1486
1487
1488 w.Reset()
1489 goroutineProf.WriteTo(&w, 0)
1490 p, err := profile.Parse(&w)
1491 if err != nil {
1492 t.Errorf("error parsing protobuf profile: %v", err)
1493 }
1494 if err := p.CheckValid(); err != nil {
1495 t.Errorf("protobuf profile is invalid: %v", err)
1496 }
1497 expectedLabels := map[int64]map[string]string{
1498 50: {},
1499 44: {"label": "value"},
1500 40: {},
1501 36: {"label": "value"},
1502 10: {},
1503 9: {"label": "value"},
1504 1: {"self-label": "self-value", "fing-label": "fing-value"},
1505 }
1506 if !containsCountsLabels(p, expectedLabels) {
1507 t.Errorf("expected count profile to contain goroutines with counts and labels %v, got %v",
1508 expectedLabels, p)
1509 }
1510
1511 close(c)
1512
1513 time.Sleep(10 * time.Millisecond)
1514 }
1515
1516 func containsInOrder(s string, all ...string) bool {
1517 for _, t := range all {
1518 var ok bool
1519 if _, s, ok = strings.Cut(s, t); !ok {
1520 return false
1521 }
1522 }
1523 return true
1524 }
1525
1526 func containsCountsLabels(prof *profile.Profile, countLabels map[int64]map[string]string) bool {
1527 m := make(map[int64]int)
1528 type nkey struct {
1529 count int64
1530 key, val string
1531 }
1532 n := make(map[nkey]int)
1533 for c, kv := range countLabels {
1534 m[c]++
1535 for k, v := range kv {
1536 n[nkey{
1537 count: c,
1538 key: k,
1539 val: v,
1540 }]++
1541
1542 }
1543 }
1544 for _, s := range prof.Sample {
1545
1546 if len(s.Value) != 1 {
1547 return false
1548 }
1549 m[s.Value[0]]--
1550 for k, vs := range s.Label {
1551 for _, v := range vs {
1552 n[nkey{
1553 count: s.Value[0],
1554 key: k,
1555 val: v,
1556 }]--
1557 }
1558 }
1559 }
1560 for _, n := range m {
1561 if n > 0 {
1562 return false
1563 }
1564 }
1565 for _, ncnt := range n {
1566 if ncnt != 0 {
1567 return false
1568 }
1569 }
1570 return true
1571 }
1572
1573
1574
1575
1576 func goroutineLeakExample() {
1577 <-make(chan struct{})
1578 panic("unreachable")
1579 }
1580
1581 func TestGoroutineLeakProfileConcurrency(t *testing.T) {
1582 const leakCount = 3
1583
1584 testenv.MustHaveParallelism(t)
1585 regexLeakCount := regexp.MustCompile("goroutineleak profile: total ")
1586 whiteSpace := regexp.MustCompile("\\s+")
1587
1588
1589
1590 goroutineProf := Lookup("goroutine")
1591 goroutineLeakProf := goroutineLeakProfile
1592
1593
1594 countLeaks := func(t *testing.T, profText string) int64 {
1595 t.Helper()
1596
1597
1598 parts := regexLeakCount.Split(profText, -1)
1599 if len(parts) < 2 {
1600 t.Fatalf("goroutineleak profile does not contain 'goroutineleak profile: total ': %s\nparts: %v", profText, parts)
1601 }
1602
1603 parts = whiteSpace.Split(parts[1], -1)
1604
1605 count, err := strconv.ParseInt(parts[0], 10, 64)
1606 if err != nil {
1607 t.Fatalf("goroutineleak profile count is not a number: %s\nerror: %v", profText, err)
1608 }
1609 return count
1610 }
1611
1612
1613
1614
1615
1616 checkFrame := func(t *testing.T, i int, j int, locations []*profile.Location, funcName string) {
1617 if len(locations) <= i {
1618 t.Errorf("leaked goroutine stack locations: out of range index %d, length %d", i, len(locations))
1619 return
1620 }
1621 location := locations[i]
1622 if len(location.Line) <= j {
1623 t.Errorf("leaked goroutine stack location lines: out of range index %d, length %d", j, len(location.Line))
1624 return
1625 }
1626 if location.Line[j].Function.Name != funcName {
1627 t.Errorf("leaked goroutine stack expected %s as location[%d].Line[%d] but found %s (%s:%d)", funcName, i, j, location.Line[j].Function.Name, location.Line[j].Function.Filename, location.Line[j].Line)
1628 }
1629 }
1630
1631
1632
1633 checkLeakStack := func(t *testing.T) func(pc uintptr, locations []*profile.Location, _ map[string][]string) {
1634 return func(pc uintptr, locations []*profile.Location, _ map[string][]string) {
1635 if pc != leakCount {
1636 t.Errorf("expected %d leaked goroutines with specific stack configurations, but found %d", leakCount, pc)
1637 return
1638 }
1639 if len(locations) < 4 || len(locations) > 5 {
1640 message := fmt.Sprintf("leaked goroutine stack expected 4 or 5 locations but found %d", len(locations))
1641 for _, location := range locations {
1642 for _, line := range location.Line {
1643 message += fmt.Sprintf("\n%s:%d", line.Function.Name, line.Line)
1644 }
1645 }
1646 t.Errorf("%s", message)
1647 return
1648 }
1649
1650 checkFrame(t, 0, 0, locations, "runtime.gopark")
1651 checkFrame(t, 1, 0, locations, "runtime.chanrecv")
1652 checkFrame(t, 2, 0, locations, "runtime.chanrecv1")
1653 checkFrame(t, 3, 0, locations, "runtime/pprof.goroutineLeakExample")
1654 if len(locations) == 5 {
1655 checkFrame(t, 4, 0, locations, "runtime/pprof.TestGoroutineLeakProfileConcurrency.func4")
1656 }
1657 }
1658 }
1659
1660
1661 const totalLeaked = leakCount * 2
1662 for i := 0; i < leakCount; i++ {
1663 go goroutineLeakExample()
1664 go func() {
1665
1666
1667 goroutineLeakExample()
1668 panic("unreachable")
1669 }()
1670 }
1671
1672
1673
1674
1675 attempts := 0
1676 startTime := time.Now()
1677 waitFor := 10 * time.Millisecond
1678 for {
1679
1680
1681 time.Sleep(waitFor)
1682
1683 var w strings.Builder
1684 goroutineLeakProf.WriteTo(&w, 1)
1685 n := countLeaks(t, w.String())
1686 if n >= totalLeaked {
1687 break
1688 }
1689
1690
1691 attempts++
1692 t.Logf("waiting for leak: attempt %d (t=%s): found %d leaked goroutines", attempts, time.Since(startTime), n)
1693
1694
1695 waitFor *= 2
1696 if waitFor > time.Second {
1697 waitFor = time.Second
1698 }
1699 }
1700
1701 t.Run("profile contains leak", func(t *testing.T) {
1702 var w strings.Builder
1703 goroutineLeakProf.WriteTo(&w, 0)
1704 parseProfile(t, []byte(w.String()), checkLeakStack(t))
1705 })
1706
1707 t.Run("leak persists between sequential profiling runs", func(t *testing.T) {
1708 for i := 0; i < 2; i++ {
1709 var w strings.Builder
1710 goroutineLeakProf.WriteTo(&w, 0)
1711 parseProfile(t, []byte(w.String()), checkLeakStack(t))
1712 }
1713 })
1714
1715
1716
1717 quickCheckForGoroutine := func(t *testing.T, profType, leak, profText string) {
1718 if !strings.Contains(profText, leak) {
1719 t.Errorf("%s profile does not contain expected leaked goroutine %s: %s", profType, leak, profText)
1720 }
1721 }
1722 t.Run("overlapping profile requests", func(t *testing.T) {
1723 ctx := context.Background()
1724 ctx, cancel := context.WithTimeout(ctx, time.Second)
1725 defer cancel()
1726
1727 var wg sync.WaitGroup
1728 for i := 0; i < 2; i++ {
1729 wg.Add(1)
1730 Do(ctx, Labels("i", fmt.Sprint(i)), func(context.Context) {
1731 go func() {
1732 defer wg.Done()
1733 for ctx.Err() == nil {
1734 var w strings.Builder
1735 goroutineLeakProf.WriteTo(&w, 1)
1736 if n := countLeaks(t, w.String()); n != totalLeaked {
1737 t.Errorf("expected %d goroutines leaked, got %d: %s", totalLeaked, n, w.String())
1738 }
1739 quickCheckForGoroutine(t, "goroutineleak", "runtime/pprof.goroutineLeakExample", w.String())
1740 }
1741 }()
1742 })
1743 }
1744 wg.Wait()
1745 })
1746
1747
1748
1749 t.Run("overlapping goroutine and goroutine leak profile requests", func(t *testing.T) {
1750 ctx := context.Background()
1751 ctx, cancel := context.WithTimeout(ctx, time.Second)
1752 defer cancel()
1753
1754 var wg sync.WaitGroup
1755 for i := 0; i < 2; i++ {
1756 wg.Add(2)
1757 Do(ctx, Labels("i", fmt.Sprint(i)), func(context.Context) {
1758 go func() {
1759 defer wg.Done()
1760 for ctx.Err() == nil {
1761 var w strings.Builder
1762 goroutineLeakProf.WriteTo(&w, 1)
1763 if n := countLeaks(t, w.String()); n != totalLeaked {
1764 t.Errorf("expected %d goroutines leaked, got %d: %s", totalLeaked, n, w.String())
1765 }
1766 quickCheckForGoroutine(t, "goroutineleak", "runtime/pprof.goroutineLeakExample", w.String())
1767 }
1768 }()
1769 go func() {
1770 defer wg.Done()
1771 for ctx.Err() == nil {
1772 var w strings.Builder
1773 goroutineProf.WriteTo(&w, 1)
1774
1775
1776
1777 quickCheckForGoroutine(t, "goroutine", "runtime/pprof.goroutineLeakExample", w.String())
1778 }
1779 }()
1780 })
1781 }
1782 wg.Wait()
1783 })
1784 }
1785
1786 func TestGoroutineProfileConcurrency(t *testing.T) {
1787 testenv.MustHaveParallelism(t)
1788
1789 goroutineProf := Lookup("goroutine")
1790
1791 profilerCalls := func(s string) int {
1792 return strings.Count(s, "\truntime/pprof.runtime_goroutineProfileWithLabels+")
1793 }
1794
1795 includesFinalizerOrCleanup := func(s string) bool {
1796 return strings.Contains(s, "runtime.runFinalizers") || strings.Contains(s, "runtime.runCleanups")
1797 }
1798
1799
1800
1801 t.Run("overlapping profile requests", func(t *testing.T) {
1802 ctx := context.Background()
1803 ctx, cancel := context.WithTimeout(ctx, 10*time.Second)
1804 defer cancel()
1805
1806 var wg sync.WaitGroup
1807 for i := 0; i < 2; i++ {
1808 wg.Add(1)
1809 Do(ctx, Labels("i", fmt.Sprint(i)), func(context.Context) {
1810 go func() {
1811 defer wg.Done()
1812 for ctx.Err() == nil {
1813 var w strings.Builder
1814 goroutineProf.WriteTo(&w, 1)
1815 prof := w.String()
1816 count := profilerCalls(prof)
1817 if count >= 2 {
1818 t.Logf("prof %d\n%s", count, prof)
1819 cancel()
1820 }
1821 }
1822 }()
1823 })
1824 }
1825 wg.Wait()
1826 })
1827
1828
1829
1830 t.Run("finalizer not present", func(t *testing.T) {
1831 var w strings.Builder
1832 goroutineProf.WriteTo(&w, 1)
1833 prof := w.String()
1834 if includesFinalizerOrCleanup(prof) {
1835 t.Errorf("profile includes finalizer or cleanup (but should be marked as system):\n%s", prof)
1836 }
1837 })
1838
1839
1840 t.Run("finalizer present", func(t *testing.T) {
1841
1842
1843
1844 type T *byte
1845 obj := new(T)
1846 ch1, ch2 := make(chan int), make(chan int)
1847 defer close(ch2)
1848 runtime.SetFinalizer(obj, func(_ any) {
1849 close(ch1)
1850 <-ch2
1851 })
1852 obj = nil
1853 for i := 10; i >= 0; i-- {
1854 select {
1855 case <-ch1:
1856 default:
1857 if i == 0 {
1858 t.Fatalf("finalizer did not run")
1859 }
1860 runtime.GC()
1861 }
1862 }
1863 var w strings.Builder
1864 goroutineProf.WriteTo(&w, 1)
1865 prof := w.String()
1866 if !includesFinalizerOrCleanup(prof) {
1867 t.Errorf("profile does not include finalizer (and it should be marked as user):\n%s", prof)
1868 }
1869 })
1870
1871
1872 testLaunches := func(t *testing.T) {
1873 var done sync.WaitGroup
1874 defer done.Wait()
1875
1876 ctx := context.Background()
1877 ctx, cancel := context.WithCancel(ctx)
1878 defer cancel()
1879
1880 ch := make(chan int)
1881 defer close(ch)
1882
1883 var ready sync.WaitGroup
1884
1885
1886
1887
1888 ready.Add(1)
1889 done.Add(1)
1890 go func() {
1891 defer done.Done()
1892 for i := 0; ctx.Err() == nil; i++ {
1893
1894
1895 SetGoroutineLabels(WithLabels(ctx, Labels(t.Name()+"-loop-i", fmt.Sprint(i))))
1896 done.Add(1)
1897 go func() {
1898 <-ch
1899 done.Done()
1900 }()
1901 for j := 0; j < i; j++ {
1902
1903
1904
1905
1906
1907
1908 runtime.Gosched()
1909 }
1910 if i == 0 {
1911 ready.Done()
1912 }
1913 }
1914 }()
1915
1916
1917
1918
1919 ready.Add(1)
1920 var churn func(i int)
1921 churn = func(i int) {
1922 SetGoroutineLabels(WithLabels(ctx, Labels(t.Name()+"-churn-i", fmt.Sprint(i))))
1923 if i == 0 {
1924 ready.Done()
1925 } else if i%16 == 0 {
1926
1927
1928 runtime.Gosched()
1929 }
1930 if ctx.Err() == nil {
1931 go churn(i + 1)
1932 }
1933 }
1934 go func() {
1935 churn(0)
1936 }()
1937
1938 ready.Wait()
1939
1940 var w [3]bytes.Buffer
1941 for i := range w {
1942 goroutineProf.WriteTo(&w[i], 0)
1943 }
1944 for i := range w {
1945 p, err := profile.Parse(bytes.NewReader(w[i].Bytes()))
1946 if err != nil {
1947 t.Errorf("error parsing protobuf profile: %v", err)
1948 }
1949
1950
1951
1952 counts := make(map[string]int)
1953 for _, s := range p.Sample {
1954 label := s.Label[t.Name()+"-loop-i"]
1955 if len(label) > 0 {
1956 counts[label[0]]++
1957 }
1958 }
1959 for j, max := 0, len(counts)-1; j <= max; j++ {
1960 n := counts[fmt.Sprint(j)]
1961 if n == 1 || (n == 2 && j == max) {
1962 continue
1963 }
1964 t.Errorf("profile #%d's goroutines with label loop-i:%d; %d != 1 (or 2 for the last entry, %d)",
1965 i+1, j, n, max)
1966 t.Logf("counts %v", counts)
1967 break
1968 }
1969 }
1970 }
1971
1972 runs := 100
1973 if testing.Short() {
1974 runs = 5
1975 }
1976 for i := 0; i < runs; i++ {
1977
1978 t.Run("goroutine launches", testLaunches)
1979 }
1980 }
1981
1982
1983 func TestGoroutineProfileCoro(t *testing.T) {
1984 testenv.MustHaveParallelism(t)
1985
1986 goroutineProf := Lookup("goroutine")
1987
1988
1989 iterFunc := func() {
1990 p, stop := iter.Pull2(
1991 func(yield func(int, int) bool) {
1992 for i := 0; i < 10000; i++ {
1993 if !yield(i, i) {
1994 return
1995 }
1996 }
1997 },
1998 )
1999 defer stop()
2000 for {
2001 _, _, ok := p()
2002 if !ok {
2003 break
2004 }
2005 }
2006 }
2007 var wg sync.WaitGroup
2008 done := make(chan struct{})
2009 wg.Add(1)
2010 go func() {
2011 defer wg.Done()
2012 for {
2013 iterFunc()
2014 select {
2015 case <-done:
2016 default:
2017 }
2018 }
2019 }()
2020
2021
2022
2023 goroutineProf.WriteTo(io.Discard, 1)
2024 }
2025
2026
2027
2028
2029 func TestGoroutineProfileIssue74090(t *testing.T) {
2030 testenv.MustHaveParallelism(t)
2031
2032 goroutineProf := Lookup("goroutine")
2033
2034
2035
2036
2037 type T *byte
2038 for range 10 {
2039
2040
2041
2042
2043
2044
2045
2046
2047 var objs []*T
2048 for range 10000 {
2049 obj := new(T)
2050 runtime.SetFinalizer(obj, func(_ any) {})
2051 objs = append(objs, obj)
2052 }
2053 objs = nil
2054
2055
2056 runtime.GC()
2057
2058
2059
2060 var w strings.Builder
2061 goroutineProf.WriteTo(&w, 1)
2062 }
2063 }
2064
2065 func BenchmarkGoroutine(b *testing.B) {
2066 withIdle := func(n int, fn func(b *testing.B)) func(b *testing.B) {
2067 return func(b *testing.B) {
2068 c := make(chan int)
2069 var ready, done sync.WaitGroup
2070 defer func() {
2071 close(c)
2072 done.Wait()
2073 }()
2074
2075 for i := 0; i < n; i++ {
2076 ready.Add(1)
2077 done.Add(1)
2078 go func() {
2079 ready.Done()
2080 <-c
2081 done.Done()
2082 }()
2083 }
2084
2085 ready.Wait()
2086 for i := 0; i < 5; i++ {
2087 runtime.Gosched()
2088 }
2089
2090 fn(b)
2091 }
2092 }
2093
2094 withChurn := func(fn func(b *testing.B)) func(b *testing.B) {
2095 return func(b *testing.B) {
2096 ctx := context.Background()
2097 ctx, cancel := context.WithCancel(ctx)
2098 defer cancel()
2099
2100 var ready sync.WaitGroup
2101 ready.Add(1)
2102 var count int64
2103 var churn func(i int)
2104 churn = func(i int) {
2105 SetGoroutineLabels(WithLabels(ctx, Labels("churn-i", fmt.Sprint(i))))
2106 atomic.AddInt64(&count, 1)
2107 if i == 0 {
2108 ready.Done()
2109 }
2110 if ctx.Err() == nil {
2111 go churn(i + 1)
2112 }
2113 }
2114 go func() {
2115 churn(0)
2116 }()
2117 ready.Wait()
2118
2119 fn(b)
2120 b.ReportMetric(float64(atomic.LoadInt64(&count))/float64(b.N), "concurrent_launches/op")
2121 }
2122 }
2123
2124 benchWriteTo := func(b *testing.B) {
2125 goroutineProf := Lookup("goroutine")
2126 b.ResetTimer()
2127 for i := 0; i < b.N; i++ {
2128 goroutineProf.WriteTo(io.Discard, 0)
2129 }
2130 b.StopTimer()
2131 }
2132
2133 benchGoroutineProfile := func(b *testing.B) {
2134 p := make([]runtime.StackRecord, 10000)
2135 b.ResetTimer()
2136 for i := 0; i < b.N; i++ {
2137 runtime.GoroutineProfile(p)
2138 }
2139 b.StopTimer()
2140 }
2141
2142
2143
2144
2145 for _, n := range []int{50, 500, 5000} {
2146 b.Run(fmt.Sprintf("Profile.WriteTo idle %d", n), withIdle(n, benchWriteTo))
2147 b.Run(fmt.Sprintf("Profile.WriteTo churn %d", n), withIdle(n, withChurn(benchWriteTo)))
2148 b.Run(fmt.Sprintf("runtime.GoroutineProfile churn %d", n), withIdle(n, withChurn(benchGoroutineProfile)))
2149 }
2150 }
2151
2152 var emptyCallStackTestRun int64
2153
2154
2155 func TestEmptyCallStack(t *testing.T) {
2156 name := fmt.Sprintf("test18836_%d", emptyCallStackTestRun)
2157 emptyCallStackTestRun++
2158
2159 t.Parallel()
2160 var buf strings.Builder
2161 p := NewProfile(name)
2162
2163 p.Add("foo", 47674)
2164 p.WriteTo(&buf, 1)
2165 p.Remove("foo")
2166 got := buf.String()
2167 prefix := name + " profile: total 1\n"
2168 if !strings.HasPrefix(got, prefix) {
2169 t.Fatalf("got:\n\t%q\nwant prefix:\n\t%q\n", got, prefix)
2170 }
2171 lostevent := "lostProfileEvent"
2172 if !strings.Contains(got, lostevent) {
2173 t.Fatalf("got:\n\t%q\ndoes not contain:\n\t%q\n", got, lostevent)
2174 }
2175 }
2176
2177
2178
2179 func stackContainsLabeled(spec string, count uintptr, stk []*profile.Location, labels map[string][]string) bool {
2180 base, kv, ok := strings.Cut(spec, ";")
2181 if !ok {
2182 panic("no semicolon in key/value spec")
2183 }
2184 k, v, ok := strings.Cut(kv, "=")
2185 if !ok {
2186 panic("missing = in key/value spec")
2187 }
2188 if !slices.Contains(labels[k], v) {
2189 return false
2190 }
2191 return stackContains(base, count, stk, labels)
2192 }
2193
2194 func TestCPUProfileLabel(t *testing.T) {
2195 matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, avoidFunctions())
2196 testCPUProfile(t, matches, func(dur time.Duration) {
2197 Do(context.Background(), Labels("key", "value"), func(context.Context) {
2198 cpuHogger(cpuHog1, &salt1, dur)
2199 })
2200 })
2201 }
2202
2203 func TestLabelRace(t *testing.T) {
2204 testenv.MustHaveParallelism(t)
2205
2206
2207
2208 matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime/pprof.cpuHogger;key=value"}, nil)
2209 testCPUProfile(t, matches, func(dur time.Duration) {
2210 start := time.Now()
2211 var wg sync.WaitGroup
2212 for time.Since(start) < dur {
2213 var salts [10]int
2214 for i := 0; i < 10; i++ {
2215 wg.Add(1)
2216 go func(j int) {
2217 Do(context.Background(), Labels("key", "value"), func(context.Context) {
2218 cpuHogger(cpuHog1, &salts[j], time.Millisecond)
2219 })
2220 wg.Done()
2221 }(i)
2222 }
2223 wg.Wait()
2224 }
2225 })
2226 }
2227
2228 func TestGoroutineProfileLabelRace(t *testing.T) {
2229 testenv.MustHaveParallelism(t)
2230
2231
2232
2233
2234 t.Run("reset", func(t *testing.T) {
2235 ctx := context.Background()
2236 ctx, cancel := context.WithCancel(ctx)
2237 defer cancel()
2238
2239 go func() {
2240 goroutineProf := Lookup("goroutine")
2241 for ctx.Err() == nil {
2242 var w strings.Builder
2243 goroutineProf.WriteTo(&w, 1)
2244 prof := w.String()
2245 if strings.Contains(prof, "loop-i") {
2246 cancel()
2247 }
2248 }
2249 }()
2250
2251 for i := 0; ctx.Err() == nil; i++ {
2252 Do(ctx, Labels("loop-i", fmt.Sprint(i)), func(ctx context.Context) {
2253 })
2254 }
2255 })
2256
2257 t.Run("churn", func(t *testing.T) {
2258 ctx := context.Background()
2259 ctx, cancel := context.WithCancel(ctx)
2260 defer cancel()
2261
2262 var ready sync.WaitGroup
2263 ready.Add(1)
2264 var churn func(i int)
2265 churn = func(i int) {
2266 SetGoroutineLabels(WithLabels(ctx, Labels("churn-i", fmt.Sprint(i))))
2267 if i == 0 {
2268 ready.Done()
2269 }
2270 if ctx.Err() == nil {
2271 go churn(i + 1)
2272 }
2273 }
2274 go func() {
2275 churn(0)
2276 }()
2277 ready.Wait()
2278
2279 goroutineProf := Lookup("goroutine")
2280 for i := 0; i < 10; i++ {
2281 goroutineProf.WriteTo(io.Discard, 1)
2282 }
2283 })
2284 }
2285
2286
2287
2288 func TestLabelSystemstack(t *testing.T) {
2289
2290
2291 gogc := debug.SetGCPercent(100)
2292 debug.SetGCPercent(gogc)
2293
2294 matches := matchAndAvoidStacks(stackContainsLabeled, []string{"runtime.systemstack;key=value"}, avoidFunctions())
2295 p := testCPUProfile(t, matches, func(dur time.Duration) {
2296 Do(context.Background(), Labels("key", "value"), func(ctx context.Context) {
2297 parallelLabelHog(ctx, dur, gogc)
2298 })
2299 })
2300
2301
2302
2303
2304 for _, s := range p.Sample {
2305 isLabeled := s.Label != nil && slices.Contains(s.Label["key"], "value")
2306 var (
2307 mayBeLabeled bool
2308 mustBeLabeled string
2309 mustNotBeLabeled string
2310 )
2311 for _, loc := range s.Location {
2312 for _, l := range loc.Line {
2313 switch l.Function.Name {
2314 case "runtime/pprof.labelHog", "runtime/pprof.parallelLabelHog", "runtime/pprof.parallelLabelHog.func1":
2315 mustBeLabeled = l.Function.Name
2316 case "runtime/pprof.Do":
2317
2318
2319
2320
2321 mayBeLabeled = true
2322 case "runtime.bgsweep", "runtime.bgscavenge", "runtime.forcegchelper", "runtime.gcBgMarkWorker", "runtime.runFinalizers", "runtime.runCleanups", "runtime.sysmon":
2323
2324
2325
2326
2327 mustNotBeLabeled = l.Function.Name
2328 case "gogo", "gosave_systemstack_switch", "racecall":
2329
2330
2331
2332
2333
2334
2335 mayBeLabeled = true
2336 }
2337
2338 if strings.HasPrefix(l.Function.Name, "runtime.") {
2339
2340
2341
2342
2343
2344
2345 mayBeLabeled = true
2346 }
2347 }
2348 }
2349 errorStack := func(f string, args ...any) {
2350 var buf strings.Builder
2351 fprintStack(&buf, s.Location)
2352 t.Errorf("%s: %s", fmt.Sprintf(f, args...), buf.String())
2353 }
2354 if mustBeLabeled != "" && mustNotBeLabeled != "" {
2355 errorStack("sample contains both %s, which must be labeled, and %s, which must not be labeled", mustBeLabeled, mustNotBeLabeled)
2356 continue
2357 }
2358 if mustBeLabeled != "" || mustNotBeLabeled != "" {
2359
2360 mayBeLabeled = false
2361 }
2362 if mayBeLabeled {
2363
2364 continue
2365 }
2366 if mustBeLabeled != "" && !isLabeled {
2367 errorStack("sample must be labeled because of %s, but is not", mustBeLabeled)
2368 }
2369 if mustNotBeLabeled != "" && isLabeled {
2370 errorStack("sample must not be labeled because of %s, but is", mustNotBeLabeled)
2371 }
2372 }
2373 }
2374
2375
2376
2377 func labelHog(stop chan struct{}, gogc int) {
2378
2379
2380 runtime.GC()
2381
2382 for i := 0; ; i++ {
2383 select {
2384 case <-stop:
2385 return
2386 default:
2387 debug.SetGCPercent(gogc)
2388 }
2389 }
2390 }
2391
2392
2393 func parallelLabelHog(ctx context.Context, dur time.Duration, gogc int) {
2394 var wg sync.WaitGroup
2395 stop := make(chan struct{})
2396 for i := 0; i < runtime.GOMAXPROCS(0); i++ {
2397 wg.Add(1)
2398 go func() {
2399 defer wg.Done()
2400 labelHog(stop, gogc)
2401 }()
2402 }
2403
2404 time.Sleep(dur)
2405 close(stop)
2406 wg.Wait()
2407 }
2408
2409
2410
2411 func TestAtomicLoadStore64(t *testing.T) {
2412 f, err := os.CreateTemp("", "profatomic")
2413 if err != nil {
2414 t.Fatalf("TempFile: %v", err)
2415 }
2416 defer os.Remove(f.Name())
2417 defer f.Close()
2418
2419 if err := StartCPUProfile(f); err != nil {
2420 t.Fatal(err)
2421 }
2422 defer StopCPUProfile()
2423
2424 var flag uint64
2425 done := make(chan bool, 1)
2426
2427 go func() {
2428 for atomic.LoadUint64(&flag) == 0 {
2429 runtime.Gosched()
2430 }
2431 done <- true
2432 }()
2433 time.Sleep(50 * time.Millisecond)
2434 atomic.StoreUint64(&flag, 1)
2435 <-done
2436 }
2437
2438 func TestTracebackAll(t *testing.T) {
2439
2440
2441 f, err := os.CreateTemp("", "proftraceback")
2442 if err != nil {
2443 t.Fatalf("TempFile: %v", err)
2444 }
2445 defer os.Remove(f.Name())
2446 defer f.Close()
2447
2448 if err := StartCPUProfile(f); err != nil {
2449 t.Fatal(err)
2450 }
2451 defer StopCPUProfile()
2452
2453 ch := make(chan int)
2454 defer close(ch)
2455
2456 count := 10
2457 for i := 0; i < count; i++ {
2458 go func() {
2459 <-ch
2460 }()
2461 }
2462
2463 N := 10000
2464 if testing.Short() {
2465 N = 500
2466 }
2467 buf := make([]byte, 10*1024)
2468 for i := 0; i < N; i++ {
2469 runtime.Stack(buf, true)
2470 }
2471 }
2472
2473
2474
2475
2476
2477
2478
2479 func TestTryAdd(t *testing.T) {
2480 if _, found := findInlinedCall(inlinedCallerDump, 4<<10); !found {
2481 t.Skip("Can't determine whether anything was inlined into inlinedCallerDump.")
2482 }
2483
2484
2485
2486 pcs := make([]uintptr, 2)
2487 inlinedCallerDump(pcs)
2488 inlinedCallerStack := make([]uint64, 2)
2489 for i := range pcs {
2490 inlinedCallerStack[i] = uint64(pcs[i])
2491 }
2492 wrapperPCs := make([]uintptr, 1)
2493 inlinedWrapperCallerDump(wrapperPCs)
2494
2495 if _, found := findInlinedCall(recursionChainBottom, 4<<10); !found {
2496 t.Skip("Can't determine whether anything was inlined into recursionChainBottom.")
2497 }
2498
2499
2500
2501
2502
2503
2504
2505 pcs = make([]uintptr, 6)
2506 recursionChainTop(1, pcs)
2507 recursionStack := make([]uint64, len(pcs))
2508 for i := range pcs {
2509 recursionStack[i] = uint64(pcs[i])
2510 }
2511
2512 period := int64(2000 * 1000)
2513
2514 testCases := []struct {
2515 name string
2516 input []uint64
2517 count int
2518 wantLocs [][]string
2519 wantSamples []*profile.Sample
2520 }{{
2521
2522 name: "full_stack_trace",
2523 input: []uint64{
2524 3, 0, 500,
2525 5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1],
2526 },
2527 count: 2,
2528 wantLocs: [][]string{
2529 {"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"},
2530 },
2531 wantSamples: []*profile.Sample{
2532 {Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
2533 },
2534 }, {
2535 name: "bug35538",
2536 input: []uint64{
2537 3, 0, 500,
2538
2539
2540
2541 7, 0, 10, inlinedCallerStack[0], inlinedCallerStack[1], inlinedCallerStack[0], inlinedCallerStack[1],
2542 5, 0, 20, inlinedCallerStack[0], inlinedCallerStack[1],
2543 },
2544 count: 3,
2545 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
2546 wantSamples: []*profile.Sample{
2547 {Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}}},
2548 {Value: []int64{20, 20 * period}, Location: []*profile.Location{{ID: 1}}},
2549 },
2550 }, {
2551 name: "bug38096",
2552 input: []uint64{
2553 3, 0, 500,
2554
2555
2556 4, 0, 0, 4242,
2557 },
2558 count: 2,
2559 wantLocs: [][]string{{"runtime/pprof.lostProfileEvent"}},
2560 wantSamples: []*profile.Sample{
2561 {Value: []int64{4242, 4242 * period}, Location: []*profile.Location{{ID: 1}}},
2562 },
2563 }, {
2564
2565
2566
2567
2568
2569
2570
2571 name: "directly_recursive_func_is_not_inlined",
2572 input: []uint64{
2573 3, 0, 500,
2574 5, 0, 30, inlinedCallerStack[0], inlinedCallerStack[0],
2575 4, 0, 40, inlinedCallerStack[0],
2576 },
2577 count: 3,
2578
2579
2580 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump"}, {"runtime/pprof.inlinedCallerDump"}},
2581 wantSamples: []*profile.Sample{
2582 {Value: []int64{30, 30 * period}, Location: []*profile.Location{{ID: 1}, {ID: 1}, {ID: 2}}},
2583 {Value: []int64{40, 40 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}}},
2584 },
2585 }, {
2586 name: "recursion_chain_inline",
2587 input: []uint64{
2588 3, 0, 500,
2589 9, 0, 10, recursionStack[0], recursionStack[1], recursionStack[2], recursionStack[3], recursionStack[4], recursionStack[5],
2590 },
2591 count: 2,
2592 wantLocs: [][]string{
2593 {"runtime/pprof.recursionChainBottom"},
2594 {
2595 "runtime/pprof.recursionChainMiddle",
2596 "runtime/pprof.recursionChainTop",
2597 "runtime/pprof.recursionChainBottom",
2598 },
2599 {
2600 "runtime/pprof.recursionChainMiddle",
2601 "runtime/pprof.recursionChainTop",
2602 "runtime/pprof.TestTryAdd",
2603 },
2604 },
2605 wantSamples: []*profile.Sample{
2606 {Value: []int64{10, 10 * period}, Location: []*profile.Location{{ID: 1}, {ID: 2}, {ID: 3}}},
2607 },
2608 }, {
2609 name: "truncated_stack_trace_later",
2610 input: []uint64{
2611 3, 0, 500,
2612 5, 0, 50, inlinedCallerStack[0], inlinedCallerStack[1],
2613 4, 0, 60, inlinedCallerStack[0],
2614 },
2615 count: 3,
2616 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
2617 wantSamples: []*profile.Sample{
2618 {Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
2619 {Value: []int64{60, 60 * period}, Location: []*profile.Location{{ID: 1}}},
2620 },
2621 }, {
2622 name: "truncated_stack_trace_first",
2623 input: []uint64{
2624 3, 0, 500,
2625 4, 0, 70, inlinedCallerStack[0],
2626 5, 0, 80, inlinedCallerStack[0], inlinedCallerStack[1],
2627 },
2628 count: 3,
2629 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
2630 wantSamples: []*profile.Sample{
2631 {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
2632 {Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 1}}},
2633 },
2634 }, {
2635
2636 name: "truncated_stack_trace_only",
2637 input: []uint64{
2638 3, 0, 500,
2639 4, 0, 70, inlinedCallerStack[0],
2640 },
2641 count: 2,
2642 wantLocs: [][]string{{"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"}},
2643 wantSamples: []*profile.Sample{
2644 {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
2645 },
2646 }, {
2647
2648 name: "truncated_stack_trace_twice",
2649 input: []uint64{
2650 3, 0, 500,
2651 4, 0, 70, inlinedCallerStack[0],
2652
2653
2654
2655 5, 0, 80, inlinedCallerStack[1], inlinedCallerStack[0],
2656 },
2657 count: 3,
2658 wantLocs: [][]string{
2659 {"runtime/pprof.inlinedCalleeDump", "runtime/pprof.inlinedCallerDump"},
2660 {"runtime/pprof.inlinedCallerDump"},
2661 },
2662 wantSamples: []*profile.Sample{
2663 {Value: []int64{70, 70 * period}, Location: []*profile.Location{{ID: 1}}},
2664 {Value: []int64{80, 80 * period}, Location: []*profile.Location{{ID: 2}, {ID: 1}}},
2665 },
2666 }, {
2667 name: "expand_wrapper_function",
2668 input: []uint64{
2669 3, 0, 500,
2670 4, 0, 50, uint64(wrapperPCs[0]),
2671 },
2672 count: 2,
2673 wantLocs: [][]string{{"runtime/pprof.inlineWrapper.dump"}},
2674 wantSamples: []*profile.Sample{
2675 {Value: []int64{50, 50 * period}, Location: []*profile.Location{{ID: 1}}},
2676 },
2677 }}
2678
2679 for _, tc := range testCases {
2680 t.Run(tc.name, func(t *testing.T) {
2681 p, err := translateCPUProfile(tc.input, tc.count)
2682 if err != nil {
2683 t.Fatalf("translating profile: %v", err)
2684 }
2685 t.Logf("Profile: %v\n", p)
2686
2687
2688 var gotLoc [][]string
2689 for _, loc := range p.Location {
2690 var names []string
2691 for _, line := range loc.Line {
2692 names = append(names, line.Function.Name)
2693 }
2694 gotLoc = append(gotLoc, names)
2695 }
2696 if got, want := fmtJSON(gotLoc), fmtJSON(tc.wantLocs); got != want {
2697 t.Errorf("Got Location = %+v\n\twant %+v", got, want)
2698 }
2699
2700 var gotSamples []*profile.Sample
2701 for _, sample := range p.Sample {
2702 var locs []*profile.Location
2703 for _, loc := range sample.Location {
2704 locs = append(locs, &profile.Location{ID: loc.ID})
2705 }
2706 gotSamples = append(gotSamples, &profile.Sample{Value: sample.Value, Location: locs})
2707 }
2708 if got, want := fmtJSON(gotSamples), fmtJSON(tc.wantSamples); got != want {
2709 t.Errorf("Got Samples = %+v\n\twant %+v", got, want)
2710 }
2711 })
2712 }
2713 }
2714
2715 func TestTimeVDSO(t *testing.T) {
2716
2717
2718
2719 if runtime.GOOS == "android" {
2720
2721 testenv.SkipFlaky(t, 48655)
2722 }
2723
2724 matches := matchAndAvoidStacks(stackContains, []string{"time.now"}, avoidFunctions())
2725 p := testCPUProfile(t, matches, func(dur time.Duration) {
2726 t0 := time.Now()
2727 for {
2728 t := time.Now()
2729 if t.Sub(t0) >= dur {
2730 return
2731 }
2732 }
2733 })
2734
2735
2736 for _, sample := range p.Sample {
2737 var seenNow bool
2738 for _, loc := range sample.Location {
2739 for _, line := range loc.Line {
2740 if line.Function.Name == "time.now" {
2741 if seenNow {
2742 t.Fatalf("unexpected recursive time.now")
2743 }
2744 seenNow = true
2745 }
2746 }
2747 }
2748 }
2749 }
2750
2751 func TestProfilerStackDepth(t *testing.T) {
2752 t.Cleanup(disableSampling())
2753
2754 const depth = 128
2755 go produceProfileEvents(t, depth)
2756 awaitBlockedGoroutine(t, "chan receive", "goroutineDeep", 1)
2757
2758 tests := []struct {
2759 profiler string
2760 prefix []string
2761 }{
2762 {"heap", []string{"runtime/pprof.allocDeep"}},
2763 {"block", []string{"runtime.chanrecv1", "runtime/pprof.blockChanDeep"}},
2764 {"mutex", []string{"sync.(*Mutex).Unlock", "runtime/pprof.blockMutexDeep"}},
2765 {"goroutine", []string{"runtime.gopark", "runtime.chanrecv", "runtime.chanrecv1", "runtime/pprof.goroutineDeep"}},
2766 }
2767
2768 for _, test := range tests {
2769 t.Run(test.profiler, func(t *testing.T) {
2770 var buf bytes.Buffer
2771 if err := Lookup(test.profiler).WriteTo(&buf, 0); err != nil {
2772 t.Fatalf("failed to write heap profile: %v", err)
2773 }
2774 p, err := profile.Parse(&buf)
2775 if err != nil {
2776 t.Fatalf("failed to parse heap profile: %v", err)
2777 }
2778 t.Logf("Profile = %v", p)
2779
2780 stks := profileStacks(p)
2781 var matchedStacks [][]string
2782 for _, stk := range stks {
2783 if !hasPrefix(stk, test.prefix) {
2784 continue
2785 }
2786
2787
2788
2789
2790 matchedStacks = append(matchedStacks, stk)
2791 if len(stk) != depth {
2792 continue
2793 }
2794 if rootFn, wantFn := stk[depth-1], "runtime/pprof.produceProfileEvents"; rootFn != wantFn {
2795 continue
2796 }
2797
2798 return
2799 }
2800 for _, stk := range matchedStacks {
2801 t.Logf("matched stack=%s", stk)
2802 if len(stk) != depth {
2803 t.Errorf("want stack depth = %d, got %d", depth, len(stk))
2804 continue
2805 }
2806
2807 if rootFn, wantFn := stk[depth-1], "runtime/pprof.allocDeep"; rootFn != wantFn {
2808 t.Errorf("want stack stack root %s, got %v", wantFn, rootFn)
2809 }
2810 }
2811 })
2812 }
2813 }
2814
2815 func hasPrefix(stk []string, prefix []string) bool {
2816 return len(prefix) <= len(stk) && slices.Equal(stk[:len(prefix)], prefix)
2817 }
2818
2819
2820 var _ = map[runtime.MemProfileRecord]struct{}{}
2821 var _ = map[runtime.StackRecord]struct{}{}
2822
2823
2824 func allocDeep(n int) {
2825 if n > 1 {
2826 allocDeep(n - 1)
2827 return
2828 }
2829 memSink = make([]byte, 1<<20)
2830 }
2831
2832
2833
2834 func blockChanDeep(t *testing.T, n int) {
2835 if n > 1 {
2836 blockChanDeep(t, n-1)
2837 return
2838 }
2839 ch := make(chan struct{})
2840 go func() {
2841 awaitBlockedGoroutine(t, "chan receive", "blockChanDeep", 1)
2842 ch <- struct{}{}
2843 }()
2844 <-ch
2845 }
2846
2847
2848
2849 func blockMutexDeep(t *testing.T, n int) {
2850 if n > 1 {
2851 blockMutexDeep(t, n-1)
2852 return
2853 }
2854 var mu sync.Mutex
2855 go func() {
2856 mu.Lock()
2857 mu.Lock()
2858 }()
2859 awaitBlockedGoroutine(t, "sync.Mutex.Lock", "blockMutexDeep", 1)
2860 mu.Unlock()
2861 }
2862
2863
2864
2865 func goroutineDeep(t *testing.T, n int) {
2866 if n > 1 {
2867 goroutineDeep(t, n-1)
2868 return
2869 }
2870 wait := make(chan struct{}, 1)
2871 t.Cleanup(func() {
2872 wait <- struct{}{}
2873 })
2874 <-wait
2875 }
2876
2877
2878
2879
2880
2881 func produceProfileEvents(t *testing.T, depth int) {
2882 allocDeep(depth - 1)
2883 blockChanDeep(t, depth-2)
2884 blockMutexDeep(t, depth-2)
2885 memSink = nil
2886 runtime.GC()
2887 goroutineDeep(t, depth-4)
2888 }
2889
2890 func getProfileStacks(collect func([]runtime.BlockProfileRecord) (int, bool), fileLine bool, pcs bool) []string {
2891 var n int
2892 var ok bool
2893 var p []runtime.BlockProfileRecord
2894 for {
2895 p = make([]runtime.BlockProfileRecord, n)
2896 n, ok = collect(p)
2897 if ok {
2898 p = p[:n]
2899 break
2900 }
2901 }
2902 var stacks []string
2903 for _, r := range p {
2904 var stack strings.Builder
2905 for i, pc := range r.Stack() {
2906 if i > 0 {
2907 stack.WriteByte('\n')
2908 }
2909 if pcs {
2910 fmt.Fprintf(&stack, "%x ", pc)
2911 }
2912
2913
2914
2915
2916
2917 f := runtime.FuncForPC(pc - 1)
2918 stack.WriteString(f.Name())
2919 if fileLine {
2920 stack.WriteByte(' ')
2921 file, line := f.FileLine(pc - 1)
2922 stack.WriteString(file)
2923 stack.WriteByte(':')
2924 stack.WriteString(strconv.Itoa(line))
2925 }
2926 }
2927 stacks = append(stacks, stack.String())
2928 }
2929 return stacks
2930 }
2931
2932 func TestMutexBlockFullAggregation(t *testing.T) {
2933
2934
2935
2936
2937 var m sync.Mutex
2938
2939 prev := runtime.SetMutexProfileFraction(-1)
2940 defer runtime.SetMutexProfileFraction(prev)
2941
2942 const fraction = 1
2943 const iters = 100
2944 const workers = 2
2945
2946 runtime.SetMutexProfileFraction(fraction)
2947 runtime.SetBlockProfileRate(1)
2948 defer runtime.SetBlockProfileRate(0)
2949
2950 wg := sync.WaitGroup{}
2951 wg.Add(workers)
2952 for range workers {
2953 go func() {
2954 for range iters {
2955 m.Lock()
2956
2957
2958 time.Sleep(time.Millisecond)
2959 m.Unlock()
2960 }
2961 wg.Done()
2962 }()
2963 }
2964 wg.Wait()
2965
2966 assertNoDuplicates := func(name string, collect func([]runtime.BlockProfileRecord) (int, bool)) {
2967 stacks := getProfileStacks(collect, true, true)
2968 seen := make(map[string]struct{})
2969 for _, s := range stacks {
2970 if _, ok := seen[s]; ok {
2971 t.Errorf("saw duplicate entry in %s profile with stack:\n%s", name, s)
2972 }
2973 seen[s] = struct{}{}
2974 }
2975 if len(seen) == 0 {
2976 t.Errorf("did not see any samples in %s profile for this test", name)
2977 }
2978 }
2979 t.Run("mutex", func(t *testing.T) {
2980 assertNoDuplicates("mutex", runtime.MutexProfile)
2981 })
2982 t.Run("block", func(t *testing.T) {
2983 assertNoDuplicates("block", runtime.BlockProfile)
2984 })
2985 }
2986
2987 func inlineA(mu *sync.Mutex, wg *sync.WaitGroup) { inlineB(mu, wg) }
2988 func inlineB(mu *sync.Mutex, wg *sync.WaitGroup) { inlineC(mu, wg) }
2989 func inlineC(mu *sync.Mutex, wg *sync.WaitGroup) {
2990 defer wg.Done()
2991 mu.Lock()
2992 mu.Unlock()
2993 }
2994
2995 func inlineD(mu *sync.Mutex, wg *sync.WaitGroup) { inlineE(mu, wg) }
2996 func inlineE(mu *sync.Mutex, wg *sync.WaitGroup) { inlineF(mu, wg) }
2997 func inlineF(mu *sync.Mutex, wg *sync.WaitGroup) {
2998 defer wg.Done()
2999 mu.Unlock()
3000 }
3001
3002 func TestBlockMutexProfileInlineExpansion(t *testing.T) {
3003 runtime.SetBlockProfileRate(1)
3004 defer runtime.SetBlockProfileRate(0)
3005 prev := runtime.SetMutexProfileFraction(1)
3006 defer runtime.SetMutexProfileFraction(prev)
3007
3008 var mu sync.Mutex
3009 var wg sync.WaitGroup
3010 wg.Add(2)
3011 mu.Lock()
3012 go inlineA(&mu, &wg)
3013 awaitBlockedGoroutine(t, "sync.Mutex.Lock", "inlineC", 1)
3014
3015 go inlineD(&mu, &wg)
3016 wg.Wait()
3017
3018 tcs := []struct {
3019 Name string
3020 Collect func([]runtime.BlockProfileRecord) (int, bool)
3021 SubStack string
3022 }{
3023 {
3024 Name: "mutex",
3025 Collect: runtime.MutexProfile,
3026 SubStack: `sync.(*Mutex).Unlock
3027 runtime/pprof.inlineF
3028 runtime/pprof.inlineE
3029 runtime/pprof.inlineD`,
3030 },
3031 {
3032 Name: "block",
3033 Collect: runtime.BlockProfile,
3034 SubStack: `sync.(*Mutex).Lock
3035 runtime/pprof.inlineC
3036 runtime/pprof.inlineB
3037 runtime/pprof.inlineA`,
3038 },
3039 }
3040
3041 for _, tc := range tcs {
3042 t.Run(tc.Name, func(t *testing.T) {
3043 stacks := getProfileStacks(tc.Collect, false, false)
3044 for _, s := range stacks {
3045 if strings.Contains(s, tc.SubStack) {
3046 return
3047 }
3048 }
3049 t.Error("did not see expected stack")
3050 t.Logf("wanted:\n%s", tc.SubStack)
3051 t.Logf("got: %s", stacks)
3052 })
3053 }
3054 }
3055
3056 func TestProfileRecordNullPadding(t *testing.T) {
3057
3058 t.Cleanup(disableSampling())
3059 memSink = make([]byte, 1)
3060 <-time.After(time.Millisecond)
3061 blockMutex(t)
3062 runtime.GC()
3063
3064
3065 testProfileRecordNullPadding(t, "MutexProfile", runtime.MutexProfile)
3066 testProfileRecordNullPadding(t, "GoroutineProfile", runtime.GoroutineProfile)
3067 testProfileRecordNullPadding(t, "BlockProfile", runtime.BlockProfile)
3068 testProfileRecordNullPadding(t, "MemProfile/inUseZero=true", func(p []runtime.MemProfileRecord) (int, bool) {
3069 return runtime.MemProfile(p, true)
3070 })
3071 testProfileRecordNullPadding(t, "MemProfile/inUseZero=false", func(p []runtime.MemProfileRecord) (int, bool) {
3072 return runtime.MemProfile(p, false)
3073 })
3074
3075 }
3076
3077 func testProfileRecordNullPadding[T runtime.StackRecord | runtime.MemProfileRecord | runtime.BlockProfileRecord](t *testing.T, name string, fn func([]T) (int, bool)) {
3078 stack0 := func(sr *T) *[32]uintptr {
3079 switch t := any(sr).(type) {
3080 case *runtime.StackRecord:
3081 return &t.Stack0
3082 case *runtime.MemProfileRecord:
3083 return &t.Stack0
3084 case *runtime.BlockProfileRecord:
3085 return &t.Stack0
3086 default:
3087 panic(fmt.Sprintf("unexpected type %T", sr))
3088 }
3089 }
3090
3091 t.Run(name, func(t *testing.T) {
3092 var p []T
3093 for {
3094 n, ok := fn(p)
3095 if ok {
3096 p = p[:n]
3097 break
3098 }
3099 p = make([]T, n*2)
3100 for i := range p {
3101 s0 := stack0(&p[i])
3102 for j := range s0 {
3103
3104 s0[j] = ^uintptr(0)
3105 }
3106 }
3107 }
3108
3109 if len(p) == 0 {
3110 t.Fatal("no records found")
3111 }
3112
3113 for _, sr := range p {
3114 for i, v := range stack0(&sr) {
3115 if v == ^uintptr(0) {
3116 t.Fatalf("record p[%d].Stack0 is not null padded: %+v", i, sr)
3117 }
3118 }
3119 }
3120 })
3121 }
3122
3123
3124
3125 func disableSampling() func() {
3126 oldMemRate := runtime.MemProfileRate
3127 runtime.MemProfileRate = 1
3128 runtime.SetBlockProfileRate(1)
3129 oldMutexRate := runtime.SetMutexProfileFraction(1)
3130 return func() {
3131 runtime.MemProfileRate = oldMemRate
3132 runtime.SetBlockProfileRate(0)
3133 runtime.SetMutexProfileFraction(oldMutexRate)
3134 }
3135 }
3136
View as plain text