# \[solved\] Agents.jl spending 3/4 of its time doing something before it even starts to compute?

**URL:** <https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109>\
**Category:** Performance\
**Created:** [August 1, 2020, 9:59pm UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109 "2020-08-01T21:59:26Z")\
**Posts on this page:** 12\
**Page:** 1

<div class="post-metadata">

**Author:** ![dlakelan](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/dlakelan/32/8491_2.png) [@dlakelan](https://discourse.julialang.org/u/dlakelan)\
**Post date:** [August 1, 2020, 9:59pm UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/1 "2020-08-01T21:59:27Z")

</div>

I’m running a simulation with 10000 agents in a continuous space. Even 4 time steps takes minutes… Netlogo can do a similar thing in milliseconds.

So of course I hit the profiler:

```julia

  131╎131 @Base/dict.jl:279; ht_keyindex(::Dict{Symbol,Int64}, ::Symbol)
     ╎13763 @Base/task.jl:358; (::REPL.var"#26#27"{REPL.REPLBackend})()
     ╎ 13763 .../julia/stdlib/v1.4/REPL/src/REPL.jl:118; macro expansion
     ╎ 13763 .../julia/stdlib/v1.4/REPL/src/REPL.jl:86; eval_user_input(::Any, ::REPL.REPLBackend)
     ╎ 13763 @Base/boot.jl:331; eval(::Module, ::Any)
     ╎ 13763 @Revise/src/Revise.jl:1165; run_backend(::REPL.REPLBackend)
     ╎ 13763 ...julia/stdlib/v1.4/REPL/src/REPL.jl:86; eval_user_input(::Any, ::REPL.REPLBackend)
     ╎42450 @Base/task.jl:444; task_done_hook(::Task)
     ╎ 42450 @Base/task.jl:709; wait
42449╎ 42450 @Base/task.jl:702; poptaskref(::Base.InvasiveLinkedListSynchronized{Task})
     ╎1 @Agents/src/simulations/collect.jl:62; (::Agents.var"#run!##kw")(::NamedTuple{(:adata, :mdata)...
     ╎ 1 @Agents/src/simulations/collect.jl:70; #run!#96
     ╎ 1 @Agents/src/simulations/collect.jl:86; (::Agents.var"#_run!##kw")(::NamedTuple{(:adata, :mdata...
     ╎ 1 @Agents/src/simulations/collect.jl:103; _run!(::AgentBasedModel{COVPerson,ContinuousSpace{type...
     ╎ 1 @Agents/src/simulations/step.jl:44; step!(::AgentBasedModel{COVPerson,ContinuousSpace{type...
     ╎ 1 REPL[130]:31; stepcovmodel!(::AgentBasedModel{COVPerson,ContinuousS...
     ╎1 @Agents/src/simulations/step.jl:44; step!(::AgentBasedModel{COVPerson,ContinuousSpace{typeo...
    1╎ 1 @Base/array.jl:678; _collect(::SubArray{COVPerson,1,Array{COVPerson,1},Tupl...
Total snapshots: 70378

```

~~I did 4 timesteps, and 10k agents, so the fact that it calls poptaskref 42449 times suggests to me that for every timestep, it pushes a task for every agent… This is incredibly inefficient and it’s spending all its time pushing and popping tasks… Of course I could be wrong.~~

It seems clear that a bunch of time is spent doing something before my calculation takes hold… I think this may be Revise or something? I’m not sure…

Here’s a profile with only 1000 agents… the big bar along the bottom is calls to `poptaskref`

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

Ok, I’m beginning to think that the lowest level calls are actually something to do with the repl/Revise… I’m still not sure why so many samples have nothing above them… All the “actual computing” comes in the last 25% of samples?

In any case, I think I’m on my way to understanding what’s making this slow. Seems like there’s a LOT of allocations, related to the way that I check for interactions between agents.

---

<div class="post-metadata">

**Author:** ![giordano](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/giordano/32/2166_2.png) [@giordano](https://discourse.julialang.org/u/giordano)\
**Post date:** [August 2, 2020, 7:01am UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/2 "2020-08-02T07:01:57Z")

</div>

> [@dlakelan](#):
>
> I think this may be Revise or something? I’m not sure…

Did you try to profile without Revise?

---

<div class="post-metadata">

**Author:** ![dlakelan](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/dlakelan/32/8491_2.png) [@dlakelan](https://discourse.julialang.org/u/dlakelan)\
**Post date:** [August 2, 2020, 4:30pm UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/3 "2020-08-02T16:30:20Z")

</div>

I will try that today. Also I am running this in a julia-repl inside emacs. not sure if that has something to do with it. I may try from regular command line

I did find that things I absolutely expected would lower the allocations increased them by 10x… so I’m pretty confused at the moment.

to elaborate on that… I had

```julia
any(map(somefn,anarray))

```

and I converted that to a loop over anarray breaking when the first time somefn returned true…

this caused my allocations to go from 1G to 10G according to benchmark…

WTH?

---

<div class="post-metadata">

**Author:** ![dlakelan](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/dlakelan/32/8491_2.png) [@dlakelan](https://discourse.julialang.org/u/dlakelan)\
**Post date:** [August 2, 2020, 5:19pm UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/4 "2020-08-02T17:19:42Z")

</div>

Here is the run outside of emacs… which was easy to do and shows that the emacs stuff isn’t the issue:

 ![image](https://global.discourse-cdn.com/julialang/original/3X/f/e/fe11973e2daa7e2de62daf62cd896cabcfd8571b.png)

And here’s after I moved my julia startup file so it wouldn’t use revise:

 ![image](https://global.discourse-cdn.com/julialang/original/3X/7/b/7bb5d2ac6b2ad1853cb48f88f1110a8f4c8dae56.png)

So, it seems that something causes 75% of my time to be used doing… nothing

and by the way this takes several seconds to run, so it’s not like the reason is that it takes a short time and some fixed few hundred milliseconds of REPL is the reason.

Here’s output from benchmarking the run! function:

```julia
BenchmarkTools.Trial: 
  memory estimate: 1.34 GiB
  allocs estimate: 32028344
  --------------
  minimum time: 6.817 s (3.54% GC)
  median time: 6.817 s (3.54% GC)
  mean time: 6.817 s (3.54% GC)
  maximum time: 6.817 s (3.54% GC)
  --------------
  samples: 1
  evals/sample: 1

```

---

<div class="post-metadata">

**Author:** ![cstjean](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/cstjean/32/1444_2.png) [@cstjean](https://discourse.julialang.org/u/cstjean)\
**Post date:** [August 2, 2020, 5:22pm UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/5 "2020-08-02T17:22:26Z")

</div>

FYI, you can do `any(somefn, anarray)`, which removes the need for the temporary in `any(map(somefn,anarray))`

---

<div class="post-metadata">

**Author:** ![dlakelan](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/dlakelan/32/8491_2.png) [@dlakelan](https://discourse.julialang.org/u/dlakelan)\
**Post date:** [August 2, 2020, 5:45pm UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/6 "2020-08-02T17:45:06Z")

</div>

Awesome, that cut my allocations in half:

```julia
BenchmarkTools.Trial: 
  memory estimate: 546.40 MiB
  allocs estimate: 15828344
  --------------
  minimum time: 6.110 s (1.35% GC)
  median time: 6.110 s (1.35% GC)
  mean time: 6.110 s (1.35% GC)
  maximum time: 6.110 s (1.35% GC)
  --------------
  samples: 1
  evals/sample: 1

```

However, as you can see, GC time is now trivial, so I’d better figure out where the heck the rest of the time is going!

---

<div class="post-metadata">

**Author:** ![dlakelan](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/dlakelan/32/8491_2.png) [@dlakelan](https://discourse.julialang.org/u/dlakelan)\
**Post date:** [August 2, 2020, 8:51pm UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/7 "2020-08-02T20:51:28Z")

</div>

AHA!

It was a bug, I was doing some code that does something for a big subset of the agents **once for every agent in the model** instead of just once…

new timing:

```julia
  memory estimate: 77.36 MiB
  allocs estimate: 1358768
  --------------
  minimum time: 323.610 ms (1.81% GC)
  median time: 331.277 ms (2.46% GC)
  mean time: 331.999 ms (2.77% GC)
  maximum time: 343.014 ms (4.23% GC)
  --------------
  samples: 16
  evals/sample: 1

```

I still don’t understand why most of the samples are coming from before my calculation starts… But hey, for the moment I’m not gonna worry about it and assume it’s some kind of overhead of running the profiler.

---

<div class="post-metadata">

**Author:** ![pkofod](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/pkofod/32/2179_2.png) [@pkofod](https://discourse.julialang.org/u/pkofod)\
**Post date:** [August 2, 2020, 9:33pm UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/8 "2020-08-02T21:33:42Z")

</div>

> [@dlakelan](#):
>
> for the moment I’m not gonna worry about it and assume it’s some kind of overhead of running the profiler.

I don’t think that’s correct, but you would have to share more for us to help.

---

<div class="post-metadata">

**Author:** ![dlakelan](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/dlakelan/32/8491_2.png) [@dlakelan](https://discourse.julialang.org/u/dlakelan)\
**Post date:** [August 2, 2020, 10:00pm UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/9 "2020-08-02T22:00:45Z")

</div>

Yeah, I don’t know either… Here’s two profile views one of which with 100 steps of my model one is 400:

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

As you can see it doesn’t matter how long I run the thing it’s always something like 25 % of the samples are in my code.

Now that I think about it, I’ve got 4 julia threads in my environment variable, so maybe it’s sampling all 4 threads, and of course 3/4 of them are not doing anything, because I’m not using threads in my code.

That must be it?

---

<div class="post-metadata">

**Author:** ![Pbellive](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/pbellive/32/3604_2.png) [@Pbellive](https://discourse.julialang.org/u/Pbellive)\
**Post date:** [August 3, 2020, 2:52am UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/10 "2020-08-03T02:52:11Z")

</div>

> [@dlakelan](#):
>
> Now that I think about it, I’ve got 4 julia threads in my environment variable, so maybe it’s sampling all 4 threads, and of course 3/4 of them are not doing anything, because I’m not using threads in my code.
> 
> That must be it?

Yeah that’s probably it. The julia profiler seems to do some funny things when julia is launched with multiple threads. See the following thread for a related example:

> [@Profiling code reveals that most time is used calling 3 functions in task.jl](https://discourse.julialang.org/t/profiling-code-reveals-that-most-time-is-used-calling-3-functions-in-task-jl/30751):
>
> I profiled my call to a function and got the following plot: Those first 3 long horizontal lines are calls to task\_done\_hook, then wait, then poptaskref (in ascending order). This happens even for the 2nd or 3rd call to my function, and I don’t understand what they could be. I stopped specifying a lot of the types used / returned in my functions after a while since I was losing time doing so properly - could this be the cause? How could I find out?

---

<div class="post-metadata">

**Author:** ![Tamas\_Papp](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/tamas_papp/32/25949_2.png) [@Tamas\_Papp](https://discourse.julialang.org/u/Tamas_Papp)\
**Post date:** [August 3, 2020, 12:54pm UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/11 "2020-08-03T12:54:40Z")

</div>

> [@dlakelan](#):
>
> Also I am running this in a julia-repl inside emacs. not sure if that has something to do with it.

It shouldn’t, that’s a plain vanilla julia process in the inferior buffer.

---

<div class="post-metadata">

**Author:** ![dlakelan](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/dlakelan/32/8491_2.png) [@dlakelan](https://discourse.julialang.org/u/dlakelan)\
**Post date:** [August 3, 2020, 3:58pm UTC](https://discourse.julialang.org/t/solved-agents-jl-spending-3-4-of-its-time-doing-something-before-it-even-starts-to-compute/44109/12 "2020-08-03T15:58:41Z")

</div>

Good to know. it seems clear this is a threads issue as my plot looks just like the plots from the linked topic.