# Massive delay when calling a fast function

**URL:** <https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120>\
**Category:** General Usage\
**Tags:** question\
**Created:** [February 12, 2024, 9:32pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120 "2024-02-12T21:32:43Z")\
**Posts on this page:** 14\
**Page:** 1

<div class="post-metadata">

**Author:** ![narnold0](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/narnold0/32/206975_2.png) [@narnold0](https://discourse.julialang.org/u/narnold0)\
**Post date:** [February 12, 2024, 9:32pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/1 "2024-02-12T21:32:43Z")

</div>

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

```julia
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?

---

<div class="post-metadata">

**Author:** ![stevengj](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/stevengj/32/71_2.png) [@stevengj](https://discourse.julialang.org/u/stevengj)\
**Post date:** [February 12, 2024, 9:39pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/2 "2024-02-12T21:39:08Z")

</div>

> [@narnold0](#):
>
> When I call this function and try to assign it to a variable, it takes like 50ms.

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)`

---

<div class="post-metadata">

**Author:** ![narnold0](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/narnold0/32/206975_2.png) [@narnold0](https://discourse.julialang.org/u/narnold0)\
**Post date:** [February 12, 2024, 9:46pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/3 "2024-02-12T21:46:27Z")

</div>

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

```julia
@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?

---

<div class="post-metadata">

**Author:** ![DNF](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/dnf/32/10191_2.png) [@DNF](https://discourse.julialang.org/u/DNF)\
**Post date:** [February 12, 2024, 9:54pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/4 "2024-02-12T21:54:14Z")

</div>

Are you saying that this takes 15us:

```julia
get_edges_to_segments(G, positions)    

```

and this takes 50ms:

```julia
result = get_edges_to_segments(G, positions)    

```

?

> [@narnold0](#):
>
> I thought that increased performance.

No, it doesn’t help.

---

<div class="post-metadata">

**Author:** ![narnold0](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/narnold0/32/206975_2.png) [@narnold0](https://discourse.julialang.org/u/narnold0)\
**Post date:** [February 12, 2024, 9:58pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/5 "2024-02-12T21:58:25Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![jar1](https://avatars.discourse-cdn.com/v4/letter/j/c0e974/32.png) [@jar1](https://discourse.julialang.org/u/jar1)\
**Post date:** [February 12, 2024, 9:59pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/6 "2024-02-12T21:59:03Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![narnold0](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/narnold0/32/206975_2.png) [@narnold0](https://discourse.julialang.org/u/narnold0)\
**Post date:** [February 12, 2024, 10:03pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/7 "2024-02-12T22:03:54Z")

</div>

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

```julia
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)

```

---

<div class="post-metadata">

**Author:** ![mkitti](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mkitti/32/12459_2.png) [@mkitti](https://discourse.julialang.org/u/mkitti)\
**Post date:** [February 12, 2024, 10:40pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/8 "2024-02-12T22:40:53Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![narnold0](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/narnold0/32/206975_2.png) [@narnold0](https://discourse.julialang.org/u/narnold0)\
**Post date:** [February 12, 2024, 10:45pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/9 "2024-02-12T22:45:58Z")

</div>

> [@mkitti](#):
>
> 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.

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

---

<div class="post-metadata">

**Author:** ![mkitti](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mkitti/32/12459_2.png) [@mkitti](https://discourse.julialang.org/u/mkitti)\
**Post date:** [February 12, 2024, 10:48pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/10 "2024-02-12T22:48:51Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![narnold0](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/narnold0/32/206975_2.png) [@narnold0](https://discourse.julialang.org/u/narnold0)\
**Post date:** [February 12, 2024, 10:55pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/11 "2024-02-12T22:55:45Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![mkitti](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mkitti/32/12459_2.png) [@mkitti](https://discourse.julialang.org/u/mkitti)\
**Post date:** [February 12, 2024, 10:56pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/12 "2024-02-12T22:56:01Z")

</div>

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

 ![image](https://global.discourse-cdn.com/julialang/original/3X/0/d/0de9ab60f4b392d8504ebe9704c56b50962c67b2.png)

Here is what some subsequent runs look like.

```julia-repl
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:

```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

```

---

<div class="post-metadata">

**Author:** ![mkitti](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mkitti/32/12459_2.png) [@mkitti](https://discourse.julialang.org/u/mkitti)\
**Post date:** [February 12, 2024, 10:57pm UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/13 "2024-02-12T22:57:45Z")

</div>

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

```julia-repl
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.

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

```

Here’s an example:

```julia-repl
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)

```

---

<div class="post-metadata">

**Author:** ![narnold0](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/narnold0/32/206975_2.png) [@narnold0](https://discourse.julialang.org/u/narnold0)\
**Post date:** [February 13, 2024, 1:48am UTC](https://discourse.julialang.org/t/massive-delay-when-calling-a-fast-function/110120/14 "2024-02-13T01:48:01Z")

</div>

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