savegif slower than GifOutput

[ederag]

With DynamicGrids v0.21.1, savegif now works (thanks !),
but it is surprinsingly slower than GifOutput.

initialization

using DynamicGrids, ColorSchemes, Colors, BenchmarkTools

const DEAD, ALIVE, BURNING = 1, 2, 3

neighbors_rule = let prob_combustion=0.0001, prob_regrowth=0.01
    Neighbors(Moore(1)) do data, neighborhood, cell, I
        if cell == ALIVE
            if BURNING in neighborhood
                BURNING
            else
                rand() <= prob_combustion ? BURNING : ALIVE
            end
        elseif cell == BURNING
            DEAD
        else
            rand() <= prob_regrowth ? ALIVE : DEAD
        end
    end
end

Then run twice (first to precompile) the following

benchmarks

# Set up the init array and output (using a Gtk window)
init = fill(ALIVE, 400, 400)
gif_output = GifOutput(init; 
    filename="forestfire.gif", tspan=1:200, fps=25, 
    minval=DEAD, maxval=BURNING, 
    scheme=ColorSchemes.rainbow,
    zerocolor=RGB24(0.0)
)

# Run the simulation, which will save a gif when it completes
print("sim GifOutput: ")
@time sim!(gif_output, neighbors_rule)

arrayoutput = ArrayOutput(init; tspan=1:200);
print("sim ArrayOutput: ")
@time sim!(arrayoutput, neighbors_rule)
print("savegif: ")
@time savegif("forest.gif", arrayoutput; fps=25, minval=DEAD, maxval=BURNING)

sim GifOutput:   3.490707 seconds (15.66 k allocations: 369.376 MiB, 0.13% gc time)
sim ArrayOutput:   0.500104 seconds (448 allocations: 2.529 MiB)
savegif:  20.820680 seconds (1.90 M allocations: 804.304 MiB, 0.13% gc time)

Tested with

  [a5dba43e] DynamicGrids v0.21.1
  [6218d12a] ImageMagick v1.2.2

[rafaqz]

Oof 20 seconds... thanks for timing this.

[rafaqz]

I can't actually reproduce this... for me its a tiny bit slower than using GifOutput, but thats because GifOutput write the gif array directly as it runs.

[ederag]

Just tested on another system, with an intel Xeon CPU (previous one was AMD), in a fresh julia environment,
and savegif is also slow:

sim GifOutput:  4.438254 seconds (15.66 k allocations: 369.376 MiB, 2.49% gc time)
sim ArrayOutput:  0.721452 seconds (448 allocations: 2.529 MiB)
savegif:  18.021740 seconds (1.52 M allocations: 765.000 MiB, 0.18% gc time)

Both are julia-1.6.4 official binaries,
on openSUSE Leap-15.3, with ImageMagick-7.0.7.34 installed, but does not seem used:

(juliadyngrid) pkg> status -m ImageMagick_jll
      Status `~/tmp/juliadyngrid/Manifest.toml`
  [c73af94c] ImageMagick_jll v6.9.10-12+3

(juliadyngrid) pkg> status
  [6e4b80f9] BenchmarkTools v1.2.2
  [35d6a980] ColorSchemes v3.15.0
  [5ae59095] Colors v0.12.8
  [a5dba43e] DynamicGrids v0.21.1
  [6218d12a] ImageMagick v1.2.2

The RAM usage hardly increases (as suggested yet not confirmed in the linked issue), but it might be this one ?
ImageMagick/ImageMagick#1824
The OP has ImageMagick-6.9.10 as well. What's your status -m ImageMagick_jll ?
Is it even possible to use a newer version in julia ?

[rafaqz]

Hmm interesting. Maybe try @profview from ProfileView.jl to see where the time us taken, and post the image here if you can.

And: ImageMagick_jll v6.9.10-12+3

[ederag]

Below is the screenshot taken after

add ProfileView
using ProfileView
@profview savegif("forest.gif", arrayoutput; fps=25, minval=DEAD, maxval=BURNING)

To anyone else, beware of timholy/ProfileView.jl#167; better do that in a separate julia environment.

CPU is 100% from the beginning, but the gif writing starts only close to the end.
On the xeon, in fresh environment without ProfileView, CPU is also 100% from the beginning,
and hitting Ctrl-C repeatedly eventually (but before the 10s half time) yields

Stacktrace:
 [1] _string_n
   @ ./strings/string.jl:74 [inlined]
 [2] string(::String, ::String)
   @ Base ./strings/substring.jl:217
 [3] *
   @ ./strings/basic.jl:260 [inlined]
 [4] joinpath(path::String, paths::String)
   @ Base.Filesystem ./path.jl:303
 [5] findfont(searchstring::String; italic::Bool, bold::Bool, additional_fonts::String)
   @ FreeTypeAbstraction ~/.julia/packages/FreeTypeAbstraction/HWI2b/src/findfonts.jl:140
 [6] findfont
   @ ~/.julia/packages/FreeTypeAbstraction/HWI2b/src/findfonts.jl:126 [inlined]
 [7] #TextConfig#120
   @ ~/.julia/packages/DynamicGrids/LSUl6/src/outputs/textconfig.jl:32 [inlined]
 [8] top-level scope
   @ ./timing.jl:210 [inlined]
 [9] top-level scope
   @ ./REPL[32]:0

autofont() finds the font, :

julia> @time DynamicGrids.autofont()
  2.324379 seconds (250.48 k allocations: 24.989 MiB, 0.26% gc time)
"cantarell"

but DynamicGrids.TextConfig takes a long time at each call (results are not cached here):

julia> @time TextConfig();
  4.632904 seconds (500.96 k allocations: 49.979 MiB, 0.14% gc time)

julia> @time TextConfig()
  4.619581 seconds (500.96 k allocations: 49.979 MiB, 0.19% gc time)
TextConfig{FreeTypeAbstraction.FTFont, Int64, Tuple{Int64, Int64}, Int64, Tuple{Int64, Int64}, ARGB32, ARGB32}(FreeTypeAbstraction.FTFont(Ptr{FreeType.__JL_FT_FaceRec_} @0x00000000013b8980, true, Dict{Char, FreeTypeAbstraction.FontExtent{Float32}}()), 12, (48, 12), 12, (24, 12), ARGB32(1.0N0f8,1.0N0f8,1.0N0f8,1.0N0f8), ARGB32(0.298N0f8,0.298N0f8,0.298N0f8,1.0N0f8))

It boils down to FreeTypeAbstraction.findfont being slow here:

julia> @time DynamicGrids.FreeTypeAbstraction.findfont("cantarell")
  2.404637 seconds (250.48 k allocations: 24.989 MiB, 3.65% gc time)
FTFont (family = Cantarell, style = Regular)

pkg> status -m FreeTypeAbstraction
 [663a7486] FreeTypeAbstraction v0.9.1`

[rafaqz]

Ok thats all fonts and FreeTypeAbstraction.jl. Guess it explains why its system specific. Thats takes essentially no time on my system (manjaro linux).

Maybe if you set the font manually?

@virgile-baudrot maybe this is why the gif output was so slow for you??

We should look around how makie do fonts its not something I really understand well.

Edit: also, why is it faster for GifOutout? How long does that take to initialise?

[virgile-baudrot]

Not sure I fully understand the issue. But I remember that rather than using GifOutput, I saved ArrayOutput and then after treatment (like saving every 5 time steps) I saved the gif file. Because indeed ArrayOutput was super fast compared to using GifOutput. System is Windows running julia with wsl ubuntu 20.04

[ederag]

Filed JuliaGraphics/FreeTypeAbstraction.jl#67 (comment) upstream.

Currently setting the font manually does not help much:

julia> @time savegif("forest.gif", arrayoutput; fps=25, minval=DEAD, maxval=BURNING, font="cantarell")
 15.396093 seconds (1.27 M allocations: 740.010 MiB, 0.17% gc time)
julia> font = DynamicGrids.FreeTypeAbstraction.findfont("cantarell")
FTFont (family = Cantarell, style = Regular)
julia> @time savegif("forest.gif", arrayoutput; fps=25, minval=DEAD, maxval=BURNING, font=font)
ERROR: ArgumentError: font FTFont (family = Cantarell, style = Regular) is not a String

It would be neat if in DynamicGrids the font= kwarg could also accept an FTFont,
and export findfont and FTFont.
Then one might either use font=findfont(font_name) to pay the search price only once,
or even use font=FTFont(path_to_font) to bypass the search altogether.

Less important, but nice: fontconfig search is fast (less than 1.3 ms here).
If font= were accepting an FTFont, then one could use the load_font() defined in my discourse question
to speed up startup as well.

We should look around how makie do fonts

Makie has its own cache, and also accept a path to specify which font to load.
https://github.com/JuliaPlots/Makie.jl/blob/9a4821bcaf1cf0f09841e659dd2a6eb81afe6527/src/conversions.jl#L922-L958

[rafaqz]

Lets accept an FTFont directly. If you feel confident implementing that a PR would be nice.

But also moving Makies cache to FreeTypAbstraction seems to make sense, we shouldn't have that implemented everywhere.

[ederag]

Lets accept an FTFont directly. If you feel confident implementing that a PR would be nice.

Good, I'm on it.