JuliaLang / julia

The Julia Programming Language
https://julialang.org/
MIT License
45.73k stars 5.49k forks source link

Inconsistent allocations reported between `@allocated` and `Profile.Allocs.@profile` #50187

Open charleskawczynski opened 1 year ago

charleskawczynski commented 1 year ago

I couldn't find an existing issue, so here goes: it seems that there's inconsistent reporting of allocations between @allocated and Profile.Allocs.@profle. Here's a MWE:

import Profile

function foo!(x)
    y = Float64[]
    for i in x
        push!(y, Float64(i))
    end
    return nothing
end

x = zero(1)
foo!(x) # compile
p_allocated = @allocated foo!(x)
@show p_allocated # 144 bytes

Profile.Allocs.clear()
Profile.Allocs.@profile sample_rate = 1 foo!(x)
results = Profile.Allocs.fetch()
sum(a -> a.size, results.allocs) # 112 bytes
julia> versioninfo()
Julia Version 1.8.5
Commit 17cfb8e65ea (2023-01-08 06:45 UTC)
Platform Info:
  OS: macOS (arm64-apple-darwin21.5.0)
  CPU: 8 × Apple M1
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-13.0.1 (ORCJIT, apple-m1)
  Threads: 1 on 4 virtual cores

Ported over from https://github.com/pfitzseb/ProfileCanvas.jl/issues/30

charleskawczynski commented 1 year ago

Can someone add the bug label to this, if they can reproduce it? 🐛

NHDaly commented 1 year ago

Hrmm interesting! I think that something is being unaccounted for in the array realloc, since the number of bytes we miss seems to have big, stepwise jumps as we scale the number of insertions:

(EDIT: and the connection to reallocs is that the array doublings only happen with the array gets full, so the stepwise growth here implies the missing allocs aren't coming from the number of insertions, since they don't grow when you add more insertions, unless the extra insertions are enough to trigger another realloc.)

Screenshot 2023-09-29 at 9 08 36 PM
import Profile

function foo!(x)
    y = Float64[]
    for i in x
        push!(y, Float64(i))
    end
    return nothing
end

foo!([0]) # compile

function missing_bytes(N)
    x = zeros(N)  # Insert more elements!
    bytes_allocated = @allocated foo!(x)

    Profile.Allocs.clear()
    Profile.Allocs.@profile sample_rate = 1 foo!(x)
    results = Profile.Allocs.fetch()
    bytes_profiled = sum(a -> a.size, results.allocs) # 112 bytes

    return bytes_allocated - bytes_profiled
end

# Plot the number of missing bytes as a function of the number of insertions

using Plots
N = 1:1000
plot(N, missing_bytes.(N), label="missing bytes")

These are the values of those flat lines:

julia> unique(missing_bytes.(N))
5-element Vector{Int64}:
  32
  40
 136
 240
 344

Weirdly, those numbers aren't multiples of each other.... 🤔 Do you think there's any chance that it's actually @allocated that's over counting?

NHDaly commented 1 year ago

It does look like the bytes allocated accounting is still a bit more complex for realloc than we are doing in the maybe_record_alloc_to_profile line at the end of this section:

https://github.com/JuliaLang/julia/blob/e5c6340e252986c0bba240a0924ee4b6885aeb65/src/gc.c#L3946-L3978

@gbaraldi: It looks like you authored some of that logic. Is there something we should be fixing in the alloc profiler invocation too? 🙏 thanks in advance! :)

bvdmitri commented 1 year ago

Can be related https://github.com/JuliaLang/julia/issues/51112

vtjnash commented 1 year ago

Array is gone, so can we close this?