Major slowdowns with Gtk + Threads

[timholy]

This may be the same issue as #325, but observed on Linux with threads. I should say I'm running this on a 6-physical-core machine (12 if you include hyperthreads). Copied from JuliaImages/ImageFiltering.jl#161 and specifically the test in timholy/ComputationalResources.jl#18:

$ JULIA_NUM_THREADS=4 julia
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.4.2-pre.0 (2020-04-15)
 _/ |\__'_|_|_|\__'_|  |  release-1.4/ef4fe83698* (fork: 122 commits, 113 days)
|__/                   |

julia> using ImageFiltering, BenchmarkTools, ComputationalResources

julia> function test_imfilter(; opt=1)
               gk = Kernel.gaussian(2.0f0)
               I = rand(Float32,1000 ,1000)
               println("julia_num_threads=$(Threads.nthreads())")
               
               for i = 1:9
                       start = time()
                       if opt == 1
                               J = imfilter(CPU1(Algorithm.FIR()), I, gk)
                       elseif opt == 2
                               J = imfilter(I, gk)
                       else
                               error("Wrong opt value $opt, either 1 (for CPU1), 2 CPUThreads")
                       end
                       t = round(time() - start, digits=6)
                       println("$i imfilter $t sec")
               end
       end
test_imfilter (generic function with 1 method)

julia> test_imfilter(opt=1)
julia_num_threads=4
1 imfilter 0.020989 sec
2 imfilter 0.022114 sec
3 imfilter 0.035968 sec
4 imfilter 0.020871 sec
5 imfilter 0.020997 sec
6 imfilter 0.021044 sec
7 imfilter 0.024659 sec
8 imfilter 0.018204 sec
9 imfilter 0.018081 sec

julia> test_imfilter(opt=2)
julia_num_threads=4
1 imfilter 0.320837 sec
2 imfilter 0.015825 sec
3 imfilter 0.018062 sec
4 imfilter 0.008963 sec
5 imfilter 0.009365 sec
6 imfilter 0.010428 sec
7 imfilter 0.009566 sec
8 imfilter 0.010779 sec
9 imfilter 0.013365 sec

All seems well. Now load Gtk and do it again:

julia> using Gtk
Gtk-Message: 09:16:09.296: Failed to load module "canberra-gtk-module"
Gtk-Message: 09:16:09.296: Failed to load module "canberra-gtk-module"

julia> test_imfilter(opt=1)
julia_num_threads=4
1 imfilter 0.020802 sec
2 imfilter 0.019717 sec
3 imfilter 0.021034 sec
4 imfilter 0.02322 sec
5 imfilter 0.017263 sec
6 imfilter 0.020025 sec
7 imfilter 0.018188 sec
8 imfilter 0.021637 sec
9 imfilter 0.017454 sec

julia> test_imfilter(opt=2)
julia_num_threads=4
1 imfilter 5.036473 sec
2 imfilter 5.020005 sec
3 imfilter 5.04309 sec
4 imfilter 0.013518 sec
5 imfilter 5.01333 sec
6 imfilter 0.032066 sec
7 imfilter 5.016917 sec
8 imfilter 5.035067 sec
9 imfilter 5.024456 sec

You can see that the multithreaded case specifically gets massively slowed down. Here are some key details:

julia> versioninfo()
Julia Version 1.4.2-pre.0
Commit ef4fe83698* (2020-04-15 16:24 UTC)
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: Intel(R) Core(TM) i7-8850H CPU @ 2.60GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-8.0.1 (ORCJIT, skylake)
Environment:
  JULIA_NUM_THREADS = 4
  JULIA_CPU_THREADS = 4

(@v1.4) pkg> st Gtk
Status `~/.julia/environments/v1.4/Project.toml`
  [4c0ca9eb] Gtk v1.1.3

[timholy]

Interestingly, I see this even on Julia 1.2, so it's not a consequence of the overhaul in threading for Julia 1.3. However, Julia 1.0.5 seems immune.

[tknopp]

How is the multithreading in imfilter implemented? Does each thread get the same amount of work? From my perspective it ist not really surprising what is happening. Gtk grabs the first CPU and thus takes most of the resources from that CPU1. I would expect that you get the speedup if you exclude the first CPU.

That Gtk.jl is resource hungry on the first CPU is another problem. If I get it right, we try to integrate the Gtk mainloop with the Julia task machinery. And that integration seems to be suboptimal. I once made a post on this in the discourse dev forum.

[tknopp]

Here is that discourse topic, where I wanted to start this discussion: https://discourse.julialang.org/t/repl-and-mainloop/35699
I think the issue is not only the fault of Gtk.jl but if you have two main loops it is somewhat unclear (at least to me) how the should behave. For instance of the "time slices" that are spend in Gtk are too long, the Julia main loop cannot on concurrent tasks.

[timholy]

Sorry we didn't get any discussion in that discourse post. I haven't looked into this deeply myself.

I can answer how the multithreading in imfilter is implemented: it uses "old school threads," see here. There doesn't seem to be a way to exclude a particular thread in Threads.@threads, so it doesn't look like there's an easy workaround.

[tknopp]

No problem, I am not in the position of solving this problem either. My feeling is that we are scratching real world problems that should actually be discussed and solved in Julia base. I see two somewhat independent problem:

• We need the notation of master / worker threads. The Threads.@threads should never run on the master thread. With that simple trick, we might already solve your issue.
• The second is how the master thread integrates with main loops and how it tries not to make the REPL "sluggish" and so on. One idea could be that the REPL does always run its code in a worker thread and keeps the master thread clean for "main-loop" related tasks. Gtk.jl could then hook into this master thread, since the drawing needs to be done on this thread anyway.

Whats you impression, what is the best forum to discuss this?

[timholy]

Sometimes fortune smiles on you (aka, Jeff's on the case): JuliaLang/julia#35552.

[tknopp]

@timholy:

There doesn't seem to be a way to exclude a particular thread in Threads.@threads, so it doesn't look like there's an easy workaround.

The following might be the answer to this particular issue:

https://tro3.github.io/ThreadPools.jl/build/index.html#ThreadPools.@bthreads

[StefanMathis]

I wasn't sure whether I should open a new thread or use this one, since I have the same problem and would like to give an answer to @tknopp's sugestion:

I tested with the following MWE:

using Gtk
using ThreadPools

main() = loop(Vector{Float64}(undef, 100_000))
function loop(arr)
    for k in 1:length(arr)
        k_float = float(k)
        arr[k] = sin(k_float)*cos(k_float)*tan(k_float)/sqrt(k_float) # Just some calculation to sink time into
    end
end

mainthreaded() = loopthreaded(Vector{Float64}(undef, 100_000))
function loopthreaded(arr)
    ThreadPools.@bthreads for k in 1:length(arr)
        k_float = float(k)
        arr[k] = sin(k_float)*cos(k_float)*tan(k_float)/sqrt(k_float) # Just some calculation to sink time into
    end
end

println("===============")
@time main()
@time mainthreaded()
@time main()
@time mainthreaded()

This results in the following output:

===============
  0.004046 seconds (2 allocations: 781.328 KiB)
  0.040130 seconds (107.68 k allocations: 11.095 MiB)
  0.004341 seconds (2 allocations: 781.328 KiB)
  0.024947 seconds (100.06 k allocations: 10.686 MiB)

So unfortunately ThreadPools.jl doesn't solve the issue.

In JuliaLang/julia#35552, it is suggested that the following line in Gtk.jl/src/GLib/signals.jl could be the culprit:

tmout_min::Cint = (uv_pollfd::_GPollFD).fd == -1 ? 10 : 5000

Changing the 5000 to 1 and voilà:

===============
  0.004263 seconds (2 allocations: 781.328 KiB)
  0.041389 seconds (107.68 k allocations: 11.095 MiB)
  0.004720 seconds (2 allocations: 781.328 KiB)
  0.025503 seconds (100.06 k allocations: 10.686 MiB)

So the problem still persists. Interestingly enough, LoopVectorization.jl is not affected.