Massive delay when calling a fast function

General Usage
1

Hey there. I’m having trouble with delay from dictionaries and functions. For example, I have a funciton that takes a graph and vertex positions that gets the edge line segments. This function itself takes <15 μs from TimerOutputs. The return is a dictionary that maps the edges to their segments.

When I call this function and try to assign it to a variable, it takes like 50ms.

Specifically, this line takes like 50ms

edges_to_segments::Dict{Tuple{Graphs.SimpleGraphs.SimpleEdge{Int64}, Int64}, GeometryBasics.Line{2, Float32}} = get_edges_to_segments(G, positions)

For clarity, splitting this line up into something like, result = get_edges_to_segments(G, positions) edges_to_segments::Dict{Tuple{Graphs.SimpleGraphs.SimpleEdge{Int64}, Int64}, GeometryBasics.Line{2, Float32}} = result . Then the line that calls the function is the one that takes ~50ms.

I don’t understand this. If the function call is only like 15microseconds of that time, then why is there this massive delay? Can I use a dict without this being so slow?

2

How are you timing it?

Assigning a function result to a variable just gives it a name, so something weird is going on.

PS. Your variable type declaration does nothing at best, and at worst will slow down the code — if you get the type wrong, it will force a conversion. Just do edges_to_segments = get_edges_to_segments(G, positions)

3

I’m timing it with just @timeit to "section1" begin ... end. The section is like 50ms but the function is almost none of that.

@timeit to "section1" begin
            
    result = get_edges_to_segments(G, positions)    
    end

For the type declarations, I had thought it was best to write them explicitly when I know what they are cause I thought that increased performance. Should I not be declaring types like that?

4

Are you saying that this takes 15us:

get_edges_to_segments(G, positions)

and this takes 50ms:

result = get_edges_to_segments(G, positions)

?

No, it doesn’t help.

5

Sorry for the bad writing and confusion. The presense of the get_edges_to_segments(G, positions) makes it take 50ms, whichever line that calls that takes the 50ms, but TimerOutputs says the function call itself is only costing 15us so I don’t know where this random time is coming from.

6

If you can share a minimal runnable example it will be easier to discuss.

1 Like
7

Here is a minimum example where you can see what I mean.

using LinearAlgebra
using Graphs
using TimerOutputs
using GeometryBasics
using NetworkLayout




const to = TimerOutput()


function testing_generate_graph()
    n = rand(45:60)
    max_edges = n * (n - 1) ÷ 2
    e = min(3 * n - 4, max_edges)
    graph = SimpleGraph(n, e)
    #graph = SimpleDiGraph(n, e)
    return graph
end

function testing_generate_layout(graph::AbstractGraph)
    layout = SFDP(Ptype = Float32, tol = 0.01, C = 0.2, K = 1)
    #layout = Spring()
    positions = layout(graph)
    return positions
end



@timeit to function get_edges_to_segments(
    graph::AbstractGraph,
    positions::Vector{GeometryBasics.Point{2,Float32}},
)
    #= 
    edges_to_segments = Dict(
        (e, i) => Segment(
            Meshes.Point(positions[src(e)][1], positions[src(e)][2]),
            Meshes.Point(positions[dst(e)][1], positions[dst(e)][2]),
        ) for (i, e) in enumerate(edges(graph))
    ) =# 
    edges_to_segments::Dict{Tuple{Graphs.SimpleGraphs.SimpleEdge{Int64}, Int64}, GeometryBasics.Line{2, Float32}} = Dict(
        (e, i) => GeometryBasics.Line(
            positions[src(e)],
           positions[dst(e)],
        ) for (i, e) in enumerate(edges(graph))
    ) 
    
    return edges_to_segments
end


G = testing_generate_graph()
vertpositions = testing_generate_layout(G)





@timeit to "section1" begin
result = get_edges_to_segments(G, vertpositions)
end 
   


to_flatten = TimerOutputs.flatten(to)    
show(to_flatten; compact = true, allocations = false)
8

It looks like you are running a script from the command line and have not done any precompilation. In this case the initial latency is likely due to the function compiling.

9

Doing this in a jupyerlab notebook. Running it multiple times doesn’t change the times beyond the variance in them.

10

Is the cell that contains the function definition in the same cell that you are running?

11

Yeah, they’re all in the same cell. I put a minimal code example above if you have access to running it atm

12

I just ran this in the Julia REPL. The initial output looks as follows.

image
image807×369 8.14 KB

Here is what some subsequent runs look like.

julia> @timeit to function get_edges_to_segments(
           graph::AbstractGraph,
           positions::Vector{GeometryBasics.Point{2,Float32}},
       )
           #=
           edges_to_segments = Dict(
               (e, i) => Segment(
                   Meshes.Point(positions[src(e)][1], positions[src(e)][2]),
                   Meshes.Point(positions[dst(e)][1], positions[dst(e)][2]),
               ) for (i, e) in enumerate(edges(graph))
           ) =#
           edges_to_segments::Dict{Tuple{Graphs.SimpleGraphs.SimpleEdge{Int64}, Int64}, GeometryBasics.Line{2, Float32}} = Dict(
               (e, i) => GeometryBasics.Line(
                   positions[src(e)],
                  positions[dst(e)],
               ) for (i, e) in enumerate(edges(graph))
           )

           return edges_to_segments
       end
get_edges_to_segments (generic function with 1 method)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.092286 seconds (40.97 k allocations: 2.980 MiB, 99.94% compilation time)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.000036 seconds (11 allocations: 52.547 KiB)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.000051 seconds (11 allocations: 52.547 KiB)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.000035 seconds (11 allocations: 52.547 KiB)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.000044 seconds (11 allocations: 52.547 KiB)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.000038 seconds (11 allocations: 52.547 KiB)

I’m a bit confused why you are trying to do a timeit around the function definition:

@timeit to function get_edges_to_segments(
    graph::AbstractGraph,
    positions::Vector{GeometryBasics.Point{2,Float32}},
)
    #= 
    edges_to_segments = Dict(
        (e, i) => Segment(
            Meshes.Point(positions[src(e)][1], positions[src(e)][2]),
            Meshes.Point(positions[dst(e)][1], positions[dst(e)][2]),
        ) for (i, e) in enumerate(edges(graph))
    ) =# 
    edges_to_segments::Dict{Tuple{Graphs.SimpleGraphs.SimpleEdge{Int64}, Int64}, GeometryBasics.Line{2, Float32}} = Dict(
        (e, i) => GeometryBasics.Line(
            positions[src(e)],
           positions[dst(e)],
        ) for (i, e) in enumerate(edges(graph))
    ) 
    
    return edges_to_segments
end
13

You should put them in separate cells. Everytime you redefine the function, you force it to recompile.

julia> function get_edges_to_segments(
           graph::AbstractGraph,
           positions::Vector{GeometryBasics.Point{2,Float32}},
       )
           #=
           edges_to_segments = Dict(
               (e, i) => Segment(
                   Meshes.Point(positions[src(e)][1], positions[src(e)][2]),
                   Meshes.Point(positions[dst(e)][1], positions[dst(e)][2]),
               ) for (i, e) in enumerate(edges(graph))
           ) =#
           edges_to_segments::Dict{Tuple{Graphs.SimpleGraphs.SimpleEdge{Int64}, Int64}, GeometryBasics.Line{2, Float32}} = Dict(
               (e, i) => GeometryBasics.Line(
                   positions[src(e)],
                  positions[dst(e)],
               ) for (i, e) in enumerate(edges(graph))
           )

           return edges_to_segments
       end
get_edges_to_segments (generic function with 1 method)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.074429 seconds (37.90 k allocations: 2.752 MiB, 99.94% compilation time)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.000032 seconds (11 allocations: 52.547 KiB)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.000045 seconds (11 allocations: 52.547 KiB)

julia> function get_edges_to_segments(
           graph::AbstractGraph,
           positions::Vector{GeometryBasics.Point{2,Float32}},
       )
           #=
           edges_to_segments = Dict(
               (e, i) => Segment(
                   Meshes.Point(positions[src(e)][1], positions[src(e)][2]),
                   Meshes.Point(positions[dst(e)][1], positions[dst(e)][2]),
               ) for (i, e) in enumerate(edges(graph))
           ) =#
           edges_to_segments::Dict{Tuple{Graphs.SimpleGraphs.SimpleEdge{Int64}, Int64}, GeometryBasics.Line{2, Float32}} = Dict(
               (e, i) => GeometryBasics.Line(
                   positions[src(e)],
                  positions[dst(e)],
               ) for (i, e) in enumerate(edges(graph))
           )

           return edges_to_segments
       end
get_edges_to_segments (generic function with 1 method)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.077947 seconds (37.90 k allocations: 2.755 MiB, 99.93% compilation time)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.000036 seconds (11 allocations: 52.547 KiB)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.000032 seconds (11 allocations: 52.547 KiB)

The compilation occurs on the first execution. Alternatively you could use a precompile statement.

precompile(get_edges_to_segments, (SimpleGraph{Int64}, Vector{Point{2, Float32}}))

Here’s an example:

julia> function get_edges_to_segments(
           graph::AbstractGraph,
           positions::Vector{GeometryBasics.Point{2,Float32}},
       )
           #=
           edges_to_segments = Dict(
               (e, i) => Segment(
                   Meshes.Point(positions[src(e)][1], positions[src(e)][2]),
                   Meshes.Point(positions[dst(e)][1], positions[dst(e)][2]),
               ) for (i, e) in enumerate(edges(graph))
           ) =#
           edges_to_segments::Dict{Tuple{Graphs.SimpleGraphs.SimpleEdge{Int64}, Int64}, GeometryBasics.Line{2, Float32}} = Dict(
               (e, i) => GeometryBasics.Line(
                   positions[src(e)],
                  positions[dst(e)],
               ) for (i, e) in enumerate(edges(graph))
           )

           return edges_to_segments
       end
get_edges_to_segments (generic function with 1 method)

julia> precompile(get_edges_to_segments, (SimpleGraph{Int64}, Vector{Point{2, Float32}})) # code will get compiled here
true

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.000038 seconds (11 allocations: 52.547 KiB)

julia> @time result = get_edges_to_segments(G, vertpositions);
  0.000038 seconds (11 allocations: 52.547 KiB)
4 Likes
14

Ahh okay, I knew the problem would seem simple in hindsight, but I didn’t realize I’ve just been using jupyter wrong this whole time lol