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

[aalexand]

$ 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))
}

[gopherbot]

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

[bradfitz]

/cc @hyangah @aclements

[hyangah]

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]

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]

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]

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]

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]

@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]

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