Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

runtime/pprof: "bytes" tag value may fluctuate between runs as it's computed off unsampled values #26638

Closed
aalexand opened this issue Jul 27, 2018 · 9 comments
Closed

runtime/pprof: "bytes" tag value may fluctuate between runs as it's computed off unsampled values #26638

aalexand opened this issue Jul 27, 2018 · 9 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Go1.12

Comments

@aalexand
Copy link
Contributor 

$ go version
go version go1.10.3 linux/amd64

See a test program and test output below. The block size allocated by the program is 32768 bytes, but the profiles contain values like 32778, 32885 and 32868. This is not quite expected - I would expect to see as the block size the exact block size I know I am allocating in the program. Looking at how the legacy profiles are handled in github.com/google/pprof (which come in sampled, so pprof has to unsample them), it looks like the block size is computed prior to unsampling the values, see https://github.com/google/pprof/blob/403a828189bee34b4b9fea51ece1af8400ccef30/profile/legacy_profile.go#L606 and https://github.com/google/pprof/blob/403a828189bee34b4b9fea51ece1af8400ccef30/profile/legacy_java_profile.go#L218.

So it looks like

go/src/runtime/pprof/protomem.go

Line 60 in bd98a81

blockSize = values[1] / values[0]
needs to be fixed to compute the block size before unsampling.

$ go test -v -memprofile mprof.out mprof_blocksize_test.go && pprof -alloc_space -tags -unit=bytes mprof.out
=== RUN   TestMprof_1
total allocated: 0.015 GiB
--- PASS: TestMprof_1 (0.00s)
PASS
ok      command-line-arguments  0.008s
 bytes: Total 8653482.0B
        8653482.0B (  100%): 32778B

$ go test -v -memprofile mprof.out mprof_blocksize_test.go && pprof -alloc_space -tags -unit=bytes mprof.out
=== RUN   TestMprof_1
total allocated: 0.015 GiB
--- PASS: TestMprof_1 (0.00s)
PASS
ok      command-line-arguments  0.007s
 bytes: Total 11357695.0B
        11357695.0B (  100%): 32825B

$ go test -v -memprofile mprof.out mprof_blocksize_test.go && pprof -alloc_space -tags -unit=bytes mprof.out
=== RUN   TestMprof_1
total allocated: 0.015 GiB
--- PASS: TestMprof_1 (0.00s)
PASS
ok      command-line-arguments  0.008s
 bytes: Total 5949269.0B
        5949269.0B (  100%): 32868B

package main

import (
        "fmt"
        "testing"
)

func alloc(iter, size int) int {
        var a []byte
        for i := 0; i < iter; i++ {
                a = make([]byte, size)
        }
        return len(a) * iter
}

func TestMprof_1(t *testing.T) {
        fmt.Printf("total allocated: %.3f GiB\n", float64(alloc(500, 32768))/(1<<30))
}
@aalexand aalexand mentioned this issue Jul 27, 2018
Closed
@gopherbot
Copy link

Change https://golang.org/cl/126336 mentions this issue: runtime/pprof: compute memory profile block size using sampled values

@bradfitz bradfitz added this to the Go1.12 milestone Jul 27, 2018
@bradfitz bradfitz added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jul 27, 2018
@bradfitz
Copy link
Contributor

/cc @hyangah @aclements

@hyangah
Copy link
Contributor

hyangah commented Aug 2, 2018

This computed block size is used for the value for the 'bytes' tag. Wouldn't it be confusing if the (scaled total bytes / scaled total object count) != the blockSize?

The utility of the 'bytes' tag is still questionable - the proposed change relies on the entire history of the allocation, but still sampled. So the value of the 'bytes' tag is still an approximate and may fluctuate over time unless the allocation object size is fixed at the call site. Wouldn't this fluctuation cause negative values in diff if the diff takes the unstable 'bytes' tag values into account?

@aalexand
Copy link
Contributor Author

aalexand commented Aug 2, 2018 •
edited

Wouldn't it be confusing if the (scaled total bytes / scaled total object count) != the blockSize?

I think it's more confusing if the value of the "bytes" tag does not match the actual allocation size, or if doing "pprof -tags -alloc_space profile2.pb.gz -base profile1.pb.gz" produces negative values for some "bytes" tags. Note that pprof itself does use the sampled values to compute the "bytes" tag when reading legacy profiles, so it seems that the behavior has changed when the runtime started producing proto output, not sure if this was intentional.

So the value of the 'bytes' tag is still an approximate and may fluctuate over time unless the allocation object size is fixed at the call site.

I believe the allocation size is a part of the bucket key when tracking allocations -

go/src/runtime/mprof.go

Line 221 in db810b6

h += size
. So I think MemProfile function returns separate records for each allocation size even if the call stack is the same.

@hyangah
Copy link
Contributor

hyangah commented Aug 3, 2018

Thanks @aalexand for reminding me that runtime maintains a separate bucket for each allocation block size. (the size here is not the user-perceived object size, but the runtime-perceived allocation size).
Yes, I think it's correct to recompute the block size using the sampled value.

@aalexand
Copy link
Contributor Author

aalexand commented Aug 3, 2018

Thanks @hyangah

the size here is not the user-perceived object size, but the runtime-perceived allocation size

Curious: when those would differ? For allocations of size that is not a multiple of something? E.g. user asks for 5 bytes but 8 bytes get allocated? Or something else?

@hyangah
Copy link
Contributor

hyangah commented Aug 3, 2018

it's complicated - see how size is changed in func mallocgc (e.g.,

go/src/runtime/malloc.go

Line 983 in 4cc09cd

profilealloc(mp, x, size)
)

@aalexand
Copy link
Contributor Author

aalexand commented Aug 4, 2018

@hyangah I think the exact accuracy of size should be discussed separately and we should get the fix https://go-review.googlesource.com/c/go/+/126336 in. WDYT?

@hyangah
Copy link
Contributor

hyangah commented Aug 6, 2018

@bradfitz should we wait till 1.12? this is a minor change but fixes the bug that leads to confusion when using tags.

@golang golang locked and limited conversation to collaborators Aug 29, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Go1.12
Development

No branches or pull requests
4 participants
@bradfitz @aalexand @hyangah @gopherbot