Julia: Major slowdown on Linux due to Gtk.jl + multithreading

[timholy]

xref https://github.com/JuliaGraphics/Gtk.jl/issues/503, which seems likely to be a Julia issue. Note that I observe it on both Julia 1.4 and 1.2, but Julia 1.0.5 does not share this problem.

[JeffBezanson]

Could you grab a profile?
Some of the new threading and task code was added in 1.2, so that makes sense.

[timholy]

Bizarrely, on a relatively recent master (8d8f46db37f6e35632df32417f24fe275aca8061) it's always fast if I use @profile:

julia> @profile test_imfilter(opt=2)
julia_num_threads=4
1 imfilter 0.019901 sec
2 imfilter 0.029619 sec
3 imfilter 0.021065 sec
4 imfilter 0.01536 sec
5 imfilter 0.013495 sec
6 imfilter 0.009861 sec
7 imfilter 0.010458 sec
8 imfilter 0.009338 sec
9 imfilter 0.020186 sec

julia> test_imfilter(opt=2)
julia_num_threads=4
1 imfilter 5.022134 sec
2 imfilter 0.034472 sec
3 imfilter 5.020989 sec
4 imfilter 5.032051 sec
5 imfilter 0.036996 sec
6 imfilter 0.017211 sec
7 imfilter 0.018399 sec
8 imfilter 0.01314 sec
9 imfilter 0.013678 sec

julia> @profile test_imfilter(opt=2)
julia_num_threads=4
1 imfilter 0.029225 sec
2 imfilter 0.010284 sec
3 imfilter 0.008963 sec
4 imfilter 0.009983 sec
5 imfilter 0.007118 sec
6 imfilter 0.012708 sec
7 imfilter 0.009843 sec
8 imfilter 0.009938 sec
9 imfilter 0.010068 sec

julia> test_imfilter(opt=2)
julia_num_threads=4
1 imfilter 0.027196 sec
2 imfilter 5.015825 sec
3 imfilter 0.032341 sec
4 imfilter 5.017424 sec
5 imfilter 0.02489 sec
6 imfilter 5.017529 sec
7 imfilter 5.018003 sec
8 imfilter 0.019033 sec
9 imfilter 5.024461 sec

If I use a low-tech sampling profiler (hit Ctrl-C and see where the break occurs), it always seems to be here:

ERROR: InterruptException:
Stacktrace:
 [1] try_yieldto(::typeof(Base.ensure_rescheduled), ::Base.RefValue{Task}) at ./task.jl:645
 [2] wait at ./task.jl:710 [inlined]
 [3] wait(::Base.GenericCondition{Base.Threads.SpinLock}) at ./condition.jl:106
 [4] _wait(::Task) at ./task.jl:238
 [5] wait(::Task) at ./task.jl:265
 [6] macro expansion at ./threadingconstructs.jl:69 [inlined]
 [7] _imfilter_tiled_threads!(::CPU1{ImageFiltering.Algorithm.FIRTiled{2}}, ::Array{Float32,2}, ::OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}}, ::OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}}, ::OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}}, ::NoPad{Pad{2}}, ::Array{Tuple{UnitRange{Int64},UnitRange{Int64}},1}, ::Array{Array{Float32,2},1}) at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:858
 [8] _imfilter_tiled!(::CPUThreads{ImageFiltering.Algorithm.FIRTiled{2}}, ::Array{Float32,2}, ::OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}}, ::Tuple{OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}},OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}}}, ::NoPad{Pad{2}}, ::Array{Array{Float32,2},1}, ::Tuple{Base.OneTo{Int64},Base.OneTo{Int64}}) at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:854
 [9] imfilter!(::CPUThreads{ImageFiltering.Algorithm.FIRTiled{2}}, ::Array{Float32,2}, ::OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}}, ::Tuple{OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}},OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}}}, ::NoPad{Pad{2}}, ::Tuple{Base.OneTo{Int64},Base.OneTo{Int64}}) at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:773
 [10] imfilter! at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:770 [inlined]
 [11] imfilter! at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:715 [inlined]
 [12] imfilter!(::CPUThreads{ImageFiltering.Algorithm.FIRTiled{2}}, ::Array{Float32,2}, ::Array{Float32,2}, ::Tuple{OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}},OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}}}, ::Pad{0}) at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:702
 [13] imfilter!(::Array{Float32,2}, ::Array{Float32,2}, ::Tuple{OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}},OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}}}, ::Pad{0}, ::ImageFiltering.Algorithm.FIRTiled{2}) at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:612
 [14] imfilter!(::Array{Float32,2}, ::Array{Float32,2}, ::Tuple{OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}},OffsetArrays.OffsetArray{Float32,2,Array{Float32,2}}}, ::Pad{0}) at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:606
 [15] imfilter at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:27 [inlined]
 [16] imfilter at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:22 [inlined]
 [17] imfilter at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:18 [inlined]
 [18] imfilter at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:10 [inlined]
 [19] imfilter at /home/tim/.julia/packages/ImageFiltering/jhBno/src/imfilter.jl:5 [inlined]
 [20] test_imfilter(; opt::Int64) at ./REPL[4]:11
 [21] top-level scope at REPL[23]:1

The threading is just old-school @threads, see here.

[JeffBezanson]

If I use a low-tech sampling profiler (hit Ctrl-C and see where the break occurs),

One of my favorites! :smile:

[JeffBezanson]

The key difference in v1.2 must be that @threads loops join at the end by calling the normal wait on tasks, which allows other scheduled tasks to run as well. Does GTK have a task scheduled that might block for 5 seconds?

[lobingera]

What do you mean?

a) Is it possible that GTK spends 5s on internal processing i.e. redrawing something?
b) Is is possible the GTK calls something that takes 5s?

I mentioned this https://github.com/JuliaGraphics/Gtk.jl/issues/325#issuecomment-396952420 , just putting the gtk main loop into a Task might not be enough. There seems to be a reason for this page https://developer.gnome.org/gtk3/stable/gtk3-General.html

[timholy]

I am no Gtk expert, but I don't think there's anything in Gtk that should take that long. Assuming that times are being measured in milliseconds, there is something which appears to be a 5s timeout. See also here. I confess that I have not dug into libuv or Julia's scheduling enough to make much sense of what's going on there.

[roflmaostc]

Hey,

I was wondering whether there are some efforts being done to fix this?
I encountered (probably?) the same issue in mcabbott/Tullio.jl#45 and Julia 1.5.2.
But for me that 5s don't appear. It's just a slowdown.

Thanks,

Felix