Profiler Timing Related to Line 0

[andrew-saydjari]

When using the profiler via ProfileSVG I sometimes see significant traceback blocks in the flame graph coming from line “0” of a notebook cell where the function was defined. An recent example is below (sorry for not being so minimal), but I really just want to know what this indicates in general. Is this saying I should be writing more type stable functions and the compiler is upset?

function build_cov!(cov,μ,cx,cy,bimage,bism,Np,widx,widy)
    Δx = (widx-1)÷2
    Δy = (widy-1)÷2
    halfNp = (Np-1) ÷ 2
    Δr, Δc = cx-(halfNp+1), cy-(halfNp+1)
    for dc=0:Np-1       # column shift loop
        pcr = 1:Np-dc
        for dr=1-Np:Np-1# row loop, incl negatives
            if (dr < 0) & (dc == 0)
                continue
            end
            if dr >= 0
                prr = 1:Np-dr
            end
            if (dr < 0) & (dc > 0)
                prr = 1-dr:Np
            end

            for pc=pcr, pr=prr
                i = ((pc   -1)*Np)+pr
                j = ((pc+dc-1)*Np)+pr+dr
                μ1μ2 = bimage[pr+Δr,pc+Δc]*bimage[pr+dr+Δr,pc+dc+Δc]/((widx*widy)^2)
                cov[i,j] = bism[pr+Δr,pc+Δc,dr+Np,dc+1]/(widx*widy) - μ1μ2
                if i == j
                    μ[i] = μ1μ2
                end
            end
        end
    end
    cov .*= (widx*widy)/((widx*widy)-1)
    return
end

cx=100
cy=100
Np = 33
cov = zeros(Np*Np,Np*Np)
μ = zeros(Np*Np)
bimage=rand(200,400)
bism=rand(200,400,2*Np-1, Np)
widx = 13
widy = 13
build_cov!(cov,μ,cx,cy,bimage,bism,Np,widx,widy)

using ProfileSVG
ProfileSVG.set_default(bgcolor=:transparent,timeunit=:s,maxframes=100000,maxdepth=300)
Profile.init(n=10^7,delay=1e-5)
ProfileSVG.@profview build_cov!(cov,μ,cx,cy,bimage,bism,Np,widx,widy)

[andrew-saydjari]

Adding @inbounds seems to reduce this traceback bar to be an order of magnitude smaller. Is time spent bound checking expected to manifest this way?

[LaurentPlagne]

I have the same question…

[LaurentPlagne]

I think that the time related to line 0 corresponds to the overhead of the profiling.
I have the impression that the real time (without profiling) is correctly predicted from the rest of the profiling data.

For example, if a given optimization leads to a profiling time, excluding the line 0 related time, that is divided by two, then the real time is effectively divided by two.

My personal conclusion is then : forget about the profiler time related to line 0.

Note that I did not investigate enough to prove this assertion.

[nsajko]

Bug report:

malformed profiling results, zero line numbers