pprof source and disasm views overcount recursive functions #707

Activity

1. kvakil commented on Jun 26, 2022

   

   kvakil

   on Jun 26, 2022

   Author

   More actions

   Forgot to mention that the graph view looks correct.

   

   The disasm view is similarly broken:

   (pprof) disasm fac
   Total: 2.43s
   ROUTINE ======================== main.fac
        2.43s      4.86s (flat, cum) 200.00% of Total
        240ms      240ms     4a6c60: CMPQ 0x10(R14), SP                      ;main.fac e.go:7
            .          .     4a6c64: JBE 0x4a6cac                            ;e.go:7
        190ms      190ms     4a6c66: SUBQ $0x10, SP                          ;main.fac e.go:7
        170ms      170ms     4a6c6a: MOVQ BP, 0x8(SP)
        220ms      220ms     4a6c6f: LEAQ 0x8(SP), BP
         60ms       60ms     4a6c74: TESTQ AX, AX                            ;main.fac e.go:8
            .          .     4a6c77: JNE 0x4a6c88                            ;e.go:8
            .          .     4a6c79: MOVL $0x1, AX                           ;e.go:9
            .          .     4a6c7e: MOVQ 0x8(SP), BP
            .          .     4a6c83: ADDQ $0x10, SP
            .          .     4a6c87: RET
         30ms       30ms     4a6c88: MOVQ AX, 0x18(SP)                       ;main.fac e.go:7
        180ms      180ms     4a6c8d: LEAQ -0x1(AX), CX                       ;main.fac e.go:11
        190ms      190ms     4a6c91: MOVQ CX, AX
         50ms      2.48s     4a6c94: CALL main.fac(SB)
            .          .     4a6c99: MOVQ 0x18(SP), CX                       ;e.go:11
        360ms      360ms     4a6c9e: IMULQ CX, AX                            ;main.fac e.go:11
        710ms      710ms     4a6ca2: MOVQ 0x8(SP), BP
         30ms       30ms     4a6ca7: ADDQ $0x10, SP
            .          .     4a6cab: RET                                     ;e.go:11
            .          .     4a6cac: MOVQ AX, 0x8(SP)                        ;e.go:7
            .          .     4a6cb1: CALL runtime.morestack_noctxt.abi0(SB)
            .          .     4a6cb6: MOVQ 0x8(SP), AX
            .          .     4a6cbb: ?
   
2. kvakil

   changed the title [-]pprof source view overcounts recursive functions[/-] [+]pprof source and disasm views overcount recursive functions[/+] on Jun 26, 2022
3. Louis-Ye

   added

   type: bugBuganizer type - BugBuganizer type - Bug

   Priority: p2Buganizer priority - P2Buganizer priority - P2

   on Jun 1, 2023
4. Hee-San commented on Sep 21, 2026

   

   Hee-San

   on Sep 21, 2026

   Contributor

   More actions

   Hi, I'd like to pick this up if nobody else has. I have two PRs for it, but the analysis first, because there turn out to be two independent bugs behind the numbers in this issue.

   One of them you already diagnosed:

   This is wrong, since the cumulative time spent in the current function is not fns.Sum() if the function calls itself recursively. In those cases some nodes will be counted multiple times.

   That's right, and it accounts for the 137.45% you got from list. It can't account for 6193% though. The Sources page has a second bug stacked on top of it. I'll call the weblist-only one A and the sum B.

   Reproduction

   A recursive fib instead of fac, so that there are two distinct recursive call sites (darwin/arm64, go1.25.0, pprof at 6331bc6):

   func fib(n int) int {
   	if n < 2 {
   		return n            // X
   	}
   	return fib(n-1) + fib(n-2)   // R1 = return address of fib(n-1), R2 = of fib(n-2)
   }

   -top is correct:

         flat  flat%   sum%        cum   cum%
        300ms 96.77% 96.77%      300ms 96.77%  main.fib
   

   The source and assembly views are not, and they don't agree with each other either. Total is 310ms:

   -list main.fib       300ms    470ms (flat, cum) 151.61% of Total
   -disasm main.fib     300ms    900ms (flat, cum) 290.32% of Total
   -weblist main.fib    300ms    8.55s (flat, cum) 2758.06%
   

   Cause A: weblist adds a sample once per stack frame

   One sample from -traces -addresses (paths trimmed):

         10ms   00000001006d466c main.fib main.go:9
                00000001006d4697 main.fib main.go:13    <- R1
                00000001006d4697 main.fib main.go:13    <- R1
                00000001006d4697 main.fib main.go:13    <- R1
                00000001006d4697 main.fib main.go:13    <- R1
                00000001006d46a7 main.fib main.go:13    <- R2
                ... 22 more main.fib frames ...
                00000001006d4697 main.fib main.go:13
                00000001006d47ab main.main main.go:26
                00000001006598b7 runtime.main proc.go:285
   

   Shortened, the shape is main.main -> fib(4) at R1 -> fib(3) at R1 -> fib(2) at R2 -> fib(0) at X. Two addresses carry the whole recursion: R1 shows up once for every frame that is inside its fib(n-1) call, R2 once for every frame inside fib(n-2).

   This sample has 29 main.fib frames: R1 nineteen times, R2 nine times, the leaf once. It is worth 10ms, and cum for an address should mean "this sample reached the address", so R1, R2 and the leaf should each get 10ms from it. newSourcePrinter instead does

   cum[addr] += value

   for every frame, so this one sample hands R1 190ms and R2 90ms.

   Over the whole profile main.fib occupies 855 frames in 30 samples, 520 of them R1 and 305 R2. At 10ms per sample that is 5.20s and 3.05s, which is exactly what the weblist page prints next to the two call instructions, and 855 × 10ms = 8.55s is its header.

   It only misfires on recursion. A function that isn't recursive has at most one frame in any sample, so each of its addresses is visited at most once and adding per frame happens to equal counting per sample. That is why none of the existing tests notice.

   It also explains your numbers. The runtime caps CPU profile stacks at 64 frames (maxCPUProfStack), so a fac(1000) sample carries roughly 62 fac frames however deep the recursion really is. 2.43s × 62 ≈ 150s, and 150s / 2.43s ≈ 6200%, which matches the 150 seconds and 6193% in your screenshot.

   This looks like a regression rather than a design choice. weblist went through rpt.newGraph until #599 (cbba55b), and newGraph keeps a seenNode set that does exactly this deduplication. The README still documents the rule:

   Samples that include a location multiple times (e.g. for recursive functions) are counted only once per location.

   With each address counted once per sample, weblist lines up with -disasm: header 900ms / 290.32%, and 300ms for each call instruction.

   Cause B: the totals are sums of overlapping parts

   Fixing A doesn't get to 100%, because the header is built by adding up its parts. -list on the same profile:

   ROUTINE ======================== main.fib in main.go
        300ms      470ms (flat, cum) 151.61% of Total
        130ms      130ms      9:func fib(n int) int {
         20ms       20ms     10:	if n < 2 {
         20ms       20ms     11:		return n
            .          .     12:	}
        130ms      300ms     13:	return fib(n-1) + fib(n-2)
            .          .     14:}
   

   Every per-line number here is already right. Line 13 says 300ms, which is exactly the cum -top reports for main.fib. Only the header is wrong, and it is wrong by construction: 130 + 20 + 20 + 300 = 470.

   cum is the weight of a set of samples, and set weights don't add:

   |A| + |B| = |A ∪ B| + |A ∩ B|
   

   so a sum overshoots by exactly the samples that reach both parts. A non-recursive function contributes one frame per sample, hence one line and one instruction, so the intersections are empty and the sum is accidentally right. Recursion is precisely the case where it isn't.

   Smallest example: one 10ms sample with three fib frames at three different addresses. Each address is correctly 10ms, but -disasm and weblist add per instruction and report 30ms, while -list adds per source line, so R1 and R2 collapse into one entry and it reports 20ms. Three granularities, three different wrong answers. The sums are at source.go#L105 (the line you linked), report.go#L454 for -disasm, and source.go#L690 and #L740 for weblist lines and functions.

   testdata/source.rpt has this checked in as an expectation: the recursive tee header is recorded at 189.90% of Total.

   What is and isn't affected

   Only the annotated source and assembly views: -list, -disasm, -weblist and the web UI Source page. -top, the graph (-dot) and the flame graph take their numbers straight from newGraph without summing anything, and their output is byte-for-byte the same before and after both fixes.

   The PRs

   Two, the second stacked on the first.

   The first fixes A: a few lines in newSourcePrinter plus a test. I don't think there is anything to decide there. It's a regression, and the rule it restores is already implemented in newGraph and written down in the README. Output for profiles without recursion is byte-for-byte unchanged.

   The second fixes B. It drops the sums and counts each sample once per function, and likewise per line in weblist, which is the rule newGraph already applies per node. It stays single-pass, so weblist doesn't get slower (0.33s before, 0.35s after, for -weblist=. on a 76,000-sample profile). With both applied, all four views report 300ms / 96.77% for main.fib. On a profile without recursion, -list, -disasm and -weblist output is byte-for-byte unchanged, and the one expectation that moves is tee in source.rpt, from 189.90% to 99.90%.

   They are separate because neither is enough alone. With only B, the weblist header says 300ms while the two call instructions under it still say 5.20s and 3.05s.

   B is more of a judgement call than A: it changes -list and -disasm output that has looked this way for years, and it rewrites a checked-in expectation. I'm sending it as a PR rather than asking first because it's easier to judge as code than as a description, but I'm not attached to it. If a maintainer would rather it worked differently, or not at all, say so and I'll close it. The one thing I'd like a view on: is "the header should match the cum that -top reports" the right goal? That's what I aimed at, and it's the part I can't settle from the code alone.
5. aalexand

   added a commit that references this issue on Sep 26, 2026

   internal/report: count each address once per sample in weblist (#1030)

   ...

   aaccee0