# Strange timing issue with code

**URL:** <https://discourse.julialang.org/t/strange-timing-issue-with-code/5230>\
**Category:** General Usage\
**Created:** [August 4, 2017, 8:23pm UTC](https://discourse.julialang.org/t/strange-timing-issue-with-code/5230 "2017-08-04T20:23:40Z")\
**Posts on this page:** 6\
**Page:** 1

<div class="post-metadata">

**Author:** ![anon94023334](https://avatars.discourse-cdn.com/v4/letter/a/e274bd/32.png) [@anon94023334](https://discourse.julialang.org/u/anon94023334)\
**Post date:** [August 4, 2017, 8:23pm UTC](https://discourse.julialang.org/t/strange-timing-issue-with-code/5230/1 "2017-08-04T20:23:40Z")

</div>

```julia
julia> @btime p = LightGraphs.dfs_parents(g, 2);
  210.919 ms (3670024 allocations: 216.13 MiB)

julia> @btime LightGraphs.tree(p);
  270.824 ms (5767200 allocations: 410.00 MiB)

julia> @btime LightGraphs.tree(LightGraphs.dfs_parents(g, 2))
  1.398 s (9437224 allocations: 626.13 MiB)

```

I’m missing something here, but why is the elapsed time so much greater for the combined functions than running them in series? Note that the allocations appear to be correctly cumulative.

ETA: `@time` is a bit more instructive, I think:

```julia
julia> @time p = LightGraphs.dfs_parents(g,2);
  0.214946 seconds (3.67 M allocations: 216.126 MiB)

julia> @time LightGraphs.tree(p);
  0.300225 seconds (5.77 M allocations: 410.001 MiB)

julia> @time LightGraphs.tree(LightGraphs.dfs_parents(g, 2));
  4.214631 seconds (9.44 M allocations: 626.127 MiB, 85.10% gc time)

```

Lots of GC time, and much worse combined performance. Is there a way to optimize away the garbage collector?

Edit 2:  
Calling `gc()` explicitly before the combined function fixes things:

```julia
julia> @time p = LightGraphs.dfs_parents(g,2);
  0.486441 seconds (3.69 M allocations: 217.065 MiB, 35.11% gc time)

julia> @time LightGraphs.tree(p);
  1.181900 seconds (5.78 M allocations: 410.747 MiB, 51.94% gc time)

julia> gc()

julia> @time LightGraphs.tree(LightGraphs.dfs_parents(g, 2))
  1.566697 seconds (9.44 M allocations: 626.127 MiB, 67.12% gc time)

```

---

<div class="post-metadata">

**Author:** ![dpsanders](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/dpsanders/32/3573_2.png) [@dpsanders](https://discourse.julialang.org/u/dpsanders)\
**Post date:** [August 4, 2017, 9:43pm UTC](https://discourse.julialang.org/t/strange-timing-issue-with-code/5230/2 "2017-08-04T21:43:58Z")

</div>

You need to use $ to interpolate the values of global variables with at-btime.

---

<div class="post-metadata">

**Author:** ![anon94023334](https://avatars.discourse-cdn.com/v4/letter/a/e274bd/32.png) [@anon94023334](https://discourse.julialang.org/u/anon94023334)\
**Post date:** [August 4, 2017, 9:44pm UTC](https://discourse.julialang.org/t/strange-timing-issue-with-code/5230/3 "2017-08-04T21:44:57Z")

</div>

@dpsanders - Thanks. I did that already, but I’m still getting similar timings. It appears to be gc-related, but I don’t quite know how to keep it from happening.

---

<div class="post-metadata">

**Author:** ![GunnarFarneback](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/gunnarfarneback/32/1827_2.png) [@GunnarFarneback](https://discourse.julialang.org/u/GunnarFarneback)\
**Post date:** [August 6, 2017, 9:25am UTC](https://discourse.julialang.org/t/strange-timing-issue-with-code/5230/4 "2017-08-06T09:25:26Z")

</div>

I don’t think you have any other resort than looking into ways of reducing your allocations. It may be possible to tweak exactly when garbage collection happens but at some point you have to pay the price for producing lots of garbage.

---

<div class="post-metadata">

**Author:** ![yuyichao](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/yuyichao/32/20_2.png) [@yuyichao](https://discourse.julialang.org/u/yuyichao)\
**Post date:** [August 6, 2017, 12:36pm UTC](https://discourse.julialang.org/t/strange-timing-issue-with-code/5230/5 "2017-08-06T12:36:28Z")

</div>

> [@GunnarFarneback](#):
>
> pay the price for producing lots of garbage.

(May or may not be related to the issue here but) just to be clear, producing garbage doesn’t have a price (other than the allocation time), producing useful allocation does…

---

<div class="post-metadata">

**Author:** ![anon94023334](https://avatars.discourse-cdn.com/v4/letter/a/e274bd/32.png) [@anon94023334](https://discourse.julialang.org/u/anon94023334)\
**Post date:** [August 7, 2017, 2:06pm UTC](https://discourse.julialang.org/t/strange-timing-issue-with-code/5230/6 "2017-08-07T14:06:00Z")

</div>

I’m still not sure why combining two functions `f(g(x))` shows such poor timing relative to `a = g(x); f(a)`.