Fatal performance degradation due to precompilation or inference bugs

[kimikage]

This is the follow-up to issue #425.

If precompilation is enabled (default), some functions will be boxed, causing significant performance degradation. For example:

julia> using Colors, BenchmarkTools # Colors.jl v0.12.8

julia> rgb_f64 = rand(RGB{Float64}, 1000, 1000);

julia> @btime convert.(XYZ, $rgb_f64);
  140.676 ms (5758522 allocations: 110.76 MiB)

This is a bug in Julia, although it has not been clearly identified, and several related issues have been reported.

• https://github.com/JuliaLang/julia/issues/34055
• https://github.com/JuliaLang/julia/issues/35537
• https://github.com/JuliaLang/julia/issues/35800
• https://github.com/JuliaLang/julia/issues/35972

"#35800" is often used as a synonym of this problem because of the memorability of the issue number.

I am not familiar with Julia's internals, so this looks very strange to me. However, I know a few things empirically. Perhaps the root cause is that inferencing is context-dependent. A typical example of context-dependency is inlining. Inlining encourages constant propagation and makes inferences more likely to succeed. We can't spend infinite time on the inference, so interrupting inferencing in a deep method chain is inevitable. The problem is that once a method fails to be inferred, it is marked as an "inference failure" until it is recompiled.

Perhaps Julia v1.6.x, the next LTS candidate, will not fully solve this problem. So we will have to live with this bug.

Of course, __precompile__(false) is a valid workaround. However, it is a last resort. There are two major approaches to workarounds. One is to make it easier for the inference to succeed (regardless of the context). The other is to avoid using "marked" (and likely to be "marked") functions.

I have implemented several workarounds in Colors v0.13 series, but the problems still remain.

Edit: A new package JETTest.jl may have less side effects than the runtime-dispatch detection based on benchmarks (such as @btime). https://discourse.julialang.org/t/ann-jettest-jl-advanced-testing-toolset-for-julia/63229

[kimikage]

Conversions

v0.12.8

from\to	RGB	HSV	XYZ	Lab	LCHab	Luv	LCHuv
RGB	:ok:	:ok:	:x:	:x:	:x:	:x:	:x:
HSV	:ok:	:ok:	:x:	:x:	:x:	:x:	:x:
XYZ	:ok:	:x:	:ok:	:x:	:x:	:ok:	:ok:
Lab	:x:	:x:	:ok:	:ok:	:ok:	:x:	:x:
LCHab	:x:	:x:	:x:	:x:	:ok:	:x:	:x:
Luv	:x:	:x:	:ok:	:x:	:x:	:ok:	:ok:
LCHuv	:x:	:x:	:x:	:x:	:x:	:ok:	:ok:

:ok: : no problem with v0.12.8 and master :x: : problematic

master

TBD

:pear: : repaired in master

script

```julia using Random using Colors rgb_f64 = rand(RGB{Float64}, 1000, 1000); rgb_f32 = rand(RGB{Float32}, 1000, 1000); hsv_f64 = HSV.(rgb_f64); hsv_f32 = HSV.(rgb_f32); xyz_f64 = XYZ.(rgb_f64); xyz_f32 = XYZ.(rgb_f32); lab_f64 = Lab.(xyz_f64); lab_f32 = Lab.(xyz_f32); lchab_f64 = LCHab.(lab_f64); lchab_f32 = LCHab.(lab_f32); luv_f64 = Luv.(xyz_f64); luv_f32 = Luv.(xyz_f32); lchuv_f64 = LCHuv.(luv_f64); lchuv_f32 = LCHuv.(luv_f32); c64 = (rgb_f64, hsv_f64, xyz_f64, lab_f64, lchab_f64, luv_f64, lchuv_f64); c32 = (rgb_f32, hsv_f32, xyz_f32, lab_f32, lchab_f32, luv_f32, lchuv_f32); Cs = shuffle([RGB, HSV, XYZ, Lab, LCHab, Luv, LCHuv]); for C in Cs println(C) for cs in c64 @show C, typeof(cs) convert.(C, cs); @time convert.(C, cs); end println() for cs in c32 @show C, typeof(cs) convert.(C, cs); @time convert.(C, cs); end println() end ```

[kimikage]

Other functions

These strongly depend on the history of compilations, making it difficult to reproduce the problem		v0.12.8	master
colordiff(::RGB{N0f8}, ::RGB{N0f8})	:x:	:pear:
colordiff(::RGB{Float32}, ::RGB{Float32})	:x:	:pear:
colordiff(::RGB{Float64}, ::RGB{Float64})	:x:	:x:
colormap(::String)	:x:	:x: (improved)
distinguishable_colors(::Int)	:x:	:pear:

distinguishable_colors still has dynamic dispatch in the output conversion, but since the output will probably only be ~100 colors at most, that is not a problem.

[kimikage]

This problem may have something to do with the recent discussion in https://github.com/JuliaLang/julia/issues/38983 (and https://github.com/JuliaLang/julia/pull/41872).

Edit: However, I don't think the invalidation is directly related to the problem, although there is a similarity in that "unnecessary" inference is re-run.

[timholy]

Does it occur reproducibly for you? And does it really depend on precompilation? For me I get this:

julia> using Colors, BenchmarkTools, Profile # Colors.jl v0.12.8

julia> rgb_f64 = rand(RGB{Float64}, 1000, 1000);

julia> @btime convert.(XYZ, $rgb_f64);
  57.859 ms (2000002 allocations: 83.92 MiB)

julia> @btime convert.(XYZ, $rgb_f64);
  28.995 ms (2 allocations: 22.89 MiB)

(Colors) pkg> st
     Project Colors v0.12.8
      Status `~/.julia/dev/Colors/Project.toml`
  [3da002f7] ColorTypes v0.11.0 `~/.julia/dev/ColorTypes`
  [53c48c17] FixedPointNumbers v0.8.4
  [189a3867] Reexport v1.0.0

julia> versioninfo()
Julia Version 1.8.0-DEV.353
Commit 2ab83f6c78* (2021-08-13 14: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-12.0.1 (ORCJIT, skylake)
Environment:
  JULIA_CPU_THREADS = 4

Moreover, I can comment out the if VERSION ... include("precompile.jl"); _precompile_(); end in both ColorTypes and Colors and it's still there. However, if I launch Julia with --compiled-modules=no then it goes away. Is that similar to what you see, or are you getting something different?

The poor performance correlates with seeing [unknown stackframe] in the C=true profile tree:

@profile @btime convert.(XYZ, $rgb_f64);    # do this on the first run when the slowdown happens
open("/tmp/proftree.txt", "w") do io
    Profile.print(IOContext(io, :displaysize=>(200,200)), C=true)
end

Then open that proftree.txt file in a text editor. Somewhere in the call chain (and it seems to vary from session to session!) I'd always see stuff like this:

   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    110   @Colors/src/conversions.jl:51; _convert
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎     110   @Colors/src/conversions.jl:309; cnvt(#unused#::Type{XYZ{Float64}}, c::RGB{Float64})
  1╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎ 110   @Colors/src/conversions.jl:283; invert_srgb_compand
 10╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎  109   [unknown stackframe]
  1╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎   1     /home/tim/src/julia-master/src/gc.c:1196; jl_gc_pool_alloc
   ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎    ╎   1     /home/tim/src/julia-master/src/gc.c:1205; jl_gc_pool_alloc

[kimikage]

Does it occur reproducibly for you?

Perhaps you are using master and not Colors v0.12.8. I have been able to reproduce the problem on Windows and Linux. The case of LCHab-->RGB is still unresolved. （cf. PR #508）

julia> using Colors # master (9c55e4a)

julia> lchab = rand(LCHab, 1000, 1000);

julia> @time convert.(RGB{Float64}, lchab);
  0.363478 seconds (4.68 M allocations: 184.190 MiB, 29.44% gc time, 40.76% compilation time)

julia> @time convert.(RGB{Float64}, lchab);
  0.095460 seconds (4.00 M allocations: 144.959 MiB, 5.01% gc time)

julia> versioninfo()
Julia Version 1.8.0-DEV.345
Commit 73e5522003 (2021-08-13 18:33 UTC)
Platform Info:
  OS: Windows (x86_64-w64-mingw32)
  CPU: 11th Gen Intel(R) Core(TM) i7-1165G7 @ 2.80GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-12.0.1 (ORCJIT, tigerlake)

[kimikage]

If you are more interested in fixing bugs in Julia and improving analysis tools than in the performance of Colors, the following MWE may be useful for you. https://github.com/JuliaLang/julia/issues/35972#issuecomment-897668397

[kimikage]

BTW, in our development flow, we bump up the dependencies just before releasing the minor versions. However, it may be better to tackle this problem with Colors and ColorTypes concurrently, i.e. to force all developers and CIs to use ColorTypes#master.

[timholy]

Fixed by https://github.com/JuliaLang/julia/pull/43990