most of the profile runtime is in task_done_hook unless threads = 1

[tpapp]

When the number of threads is not 1, a lot of time is reported in task_done_hook. This makes profiling results confusing. julia -t 1 is a workaround.

julia> VERSION
v"1.8.0-DEV.271"

julia> using Profile

julia> f(n) = [sum(randn(100)) for _ in 1:n]
f (generic function with 1 method)

julia> f(1);

julia> @profile f(10^5);

julia> Profile.print(; maxdepth = 3)
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
   ╎261  @Base/client.jl:495; _start()
   ╎ 261  @Base/client.jl:309; exec_options(opts::Base.JLOptions)
   ╎  261  @Base/client.jl:379; run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_file::Bool, color_set::Bool)
   ╎   261  @Base/essentials.jl:716; invokelatest
   ╎530  @Base/task.jl:531; task_done_hook(t::Task)
   ╎ 530  @Base/task.jl:823; wait()
529╎  530  @Base/task.jl:814; poptask(W::Base.InvasiveLinkedListSynchronized{Task})
   ╎265  @Base/threadingconstructs.jl:178; (::Distributed.var"#145#147")()
   ╎ 265  @Distributed/src/remotecall.jl:260; macro expansion
   ╎  265  @Base/condition.jl:78; lock
   ╎   265  @Base/lock.jl:187; lock(f::Distributed.var"#146#148", l::ReentrantLock)
  1╎1    @Random/src/normal.jl:38; randn(rng::Random.TaskLocalRNG)
  2╎2    @Random/src/normal.jl:70; randn_unlikely(rng::Random.TaskLocalRNG, idx::Int64, rabs::Int64, x::Float64)
Total snapshots: 1060

[vchuravy]

Related to #39746

Profiling right now is not really up to snuff for multi-threaded programs in general. https://golang.org/doc/diagnostics has a couple of nifty features.

[JeffBezanson]

Right; notice the time is actually inside wait(), which is just where we pick another task to run, or block. I want to get rid of task_done_hook, but at least this doesn't seem to indicate it's using a lot of CPU.

[tpapp]

Would some post-processing of the profiling results (remove the outer task-related thingies) be a reasonable workaround?