Confusion regarding Threads.@spawn performance

General Usage
5

This is because the scheduler stops the current task (which is executing the REPL) and start executing the other tasks waiting for the CPU resource.

Here is a self-contained MWE:

function intensive_computation()
    started = time_ns()
    while time_ns() - started < 1_000_000_000
    end
end

@show Threads.nthreads()
let t0 = time_ns()
    tasks = [Threads.@spawn(intensive_computation()) for _ in 1:Threads.nthreads()]
    t1 = time_ns()
    print("all ")
    t2 = time_ns()
    println("spawned")
    t3 = time_ns()
    foreach(wait, tasks)
    t4 = time_ns()
    @show (t1 - t0) / 1_000_000
    @show (t2 - t1) / 1_000_000
    @show (t3 - t2) / 1_000_000
    @show (t4 - t3) / 1_000_000
end

With julia1.5 -t2, it prints

Threads.nthreads() = 2
all spawned
(t1 - t0) / 1000000 = 38.178896
(t2 - t1) / 1000000 = 1002.921738
(t3 - t2) / 1000000 = 0.052758
(t4 - t3) / 1000000 = 7.701817

Notice that t1-to-t2 (which just calls print("all ")) is the longest and it matches with the total computation time required for this MWE. If you run this, you can see that it “hangs” briefly just after printing all. That is to say, the I/O print("all ") looks like blocking the execution. The julia runtime tries to share the CPU resource fairly to the tasks and switches to one of the Threads.@spawn(intensive_computation()) task, hoping they let go the CPU “soon enough.” However, this doesn’t happen with compute-intensive task, especially when you are ccalling external libraries.

I think this is happening in the @time example in the OP. Indeed, Base.time_print called from @time first prints empty spaces (typically)

https://github.com/JuliaLang/julia/blob/b07594dac02dc5a8e01c14444d63a27a131ebe7d/base/timing.jl#L105-L107

So, it looks like print("all ") in the MWE that blocks printing the rest of the result. My guess is that you’d see what you expected (~100 ms) if you waited long enough for all the task to complete (~100 seconds?). Here is what I see with 10 tasks:

julia> @time svdvals(rand(1000, 1000));
  0.171515 seconds (11 allocations: 15.839 MiB)

julia> t0 = time_ns()
       @time [Threads.@spawn svdvals(rand(1000, 1000)) for _ in 1:10]
       t1 = time_ns()
       (t1 - t0) / 10^9
  0.032784 seconds (51.69 k allocations: 3.062 MiB)
1.909254835

Notice that the time to complete the full @time ... expression is much longer than what @time itself reports.

3 Likes