Time to first plot in Gadfly is very slow even after Gadfly has been precompiled. #921

ViralBShah · 2016-10-16T17:14:24Z

Gadfly precompilation even though slow, is a one time thing - and after that using Gadfly is fast. However, even then, the first plot in a clean Julia session typically takes 20-30 seconds.

It seems that the time is all spent in compiling stringmime("text/html", plot(...)) that prepares all the rendering. From the second time onwards, this all takes a split second.

Is there any way to add precompile hints for stringmime to improve the time for the first plot?

The text was updated successfully, but these errors were encountered:

ViralBShah · 2016-10-16T17:15:07Z

Cc @vtjnash @MikeInnes @shashi

tlnagy · 2016-10-16T19:47:52Z

Could you share the results of profiling Gadfly? I think this is a high priority issue since the time till first plot is excessive.

ViralBShah · 2016-10-17T10:57:16Z

I haven't run the profiler on it. Based on the timings, my understanding is that we need to more aggressively precompile stringmime, but I will try and profile too.

tlnagy · 2016-10-17T17:54:15Z

I tried adding

precompile(Gadfly.stringmime, (AbstractString, Void))
precompile(Gadfly.stringmime, (MIME{Symbol("text/html")}, Void))

to precompile.jl, but it didn't seem to make a difference in speed.

MikeInnes · 2016-10-17T17:58:42Z

Calling precompile on that function won't make a lot of difference because the compiler won't be able to infer the whole call chain. But you could try actually calling stringmime with an example plot. The method that are compiled within the gadfly module as this runs will be cached.

I suspect that much of the time is spent in compose.jl and perhaps other dependencies, but we may be able to add similar calls to those as well.

tlnagy · 2016-10-17T18:07:37Z

Ah.

Adding stringmime("text/html", plot(x=1:5, y=1:5, Geom.line)) to precompile.jl didn't make a difference, while stringmime(MIME{Symbol("text/html")}, plot(x=1:5, y=1:5, Geom.line)) crashes:

ERROR: LoadError: MethodError: no method matching stringmime(::Type{MIME{Symbol("text/html")}}, ::Gadfly.Plot)
Closest candidates are:
  stringmime(::MIME{Symbol("text/vnd.graphviz")}, ::Any) at multimedia.jl:65
  stringmime(::MIME{Symbol("text/latex")}, ::Any) at multimedia.jl:65
  stringmime(::MIME{Symbol("text/calendar")}, ::Any) at multimedia.jl:65
  ...
 in _precompile_() at /Users/tamasnagy/.julia/v0.5/Gadfly/src/precompile.jl:863
 in include_from_node1(::String) at ./loading.jl:488
 in include_from_node1(::String) at /Applications/Julia-0.5.app/Contents/Resources/julia/lib/julia/sys.dylib:?
 in macro expansion; at ./none:2 [inlined]
 in anonymous at ./<missing>:?
 in eval(::Module, ::Any) at ./boot.jl:234
 in eval(::Module, ::Any) at /Applications/Julia-0.5.app/Contents/Resources/julia/lib/julia/sys.dylib:?
 in process_options(::Base.JLOptions) at ./client.jl:239
 in _start() at ./client.jl:318
 in _start() at /Applications/Julia-0.5.app/Contents/Resources/julia/lib/julia/sys.dylib:?
while loading /Users/tamasnagy/.julia/v0.5/Gadfly/src/Gadfly.jl, in expression starting on line 1272
ERROR: Failed to precompile Gadfly to /Users/tamasnagy/.julia/lib/v0.5/Gadfly.ji.
 in compilecache(::String) at ./loading.jl:593
 in require(::Symbol) at ./loading.jl:393
 in require(::Symbol) at /Applications/Julia-0.5.app/Contents/Resources/julia/lib/julia/sys.dylib:?

which is interesting

MikeInnes · 2016-10-17T19:01:00Z

Make sure to instantiate the mime type. There's a neater string macro as
well.

Anyway if there's no difference that points to the compiler time being in
dependencies, I think.

On Mon, 17 Oct 2016, 19:07 Tamas Nagy, notifications@github.com wrote:

Ah.

Adding stringmime("text/html", plot(x=1:5, y=1:5, Geom.line)) to
precompile.jl didn't make a difference, while stringmime(MIME{Symbol("text/html")},
plot(x=1:5, y=1:5, Geom.line)) crashes:

ERROR: LoadError: MethodError: no method matching stringmime(::Type{MIME{Symbol("text/html")}}, ::Gadfly.Plot)
Closest candidates are:
stringmime(::MIME{Symbol("text/vnd.graphviz")}, ::Any) at multimedia.jl:65
stringmime(::MIME{Symbol("text/latex")}, ::Any) at multimedia.jl:65
stringmime(::MIME{Symbol("text/calendar")}, ::Any) at multimedia.jl:65
...
in precompile() at /Users/tamasnagy/.julia/v0.5/Gadfly/src/precompile.jl:863
in include_from_node1(::String) at ./loading.jl:488
in include_from_node1(::String) at /Applications/Julia-0.5.app/Contents/Resources/julia/lib/julia/sys.dylib:?
in macro expansion; at ./none:2 [inlined]
in anonymous at ./:?
in eval(::Module, ::Any) at ./boot.jl:234
in eval(::Module, ::Any) at /Applications/Julia-0.5.app/Contents/Resources/julia/lib/julia/sys.dylib:?
in process_options(::Base.JLOptions) at ./client.jl:239
in _start() at ./client.jl:318
in _start() at /Applications/Julia-0.5.app/Contents/Resources/julia/lib/julia/sys.dylib:?
while loading /Users/tamasnagy/.julia/v0.5/Gadfly/src/Gadfly.jl, in expression starting on line 1272
ERROR: Failed to precompile Gadfly to /Users/tamasnagy/.julia/lib/v0.5/Gadfly.ji.
in compilecache(::String) at ./loading.jl:593
in require(::Symbol) at ./loading.jl:393
in require(::Symbol) at /Applications/Julia-0.5.app/Contents/Resources/julia/lib/julia/sys.dylib:?

which is interesting

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#921 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACIY9u1775YJVDdEOvkleuhirsE-GoaZks5q07lrgaJpZM4KYBfg
.

aviks · 2016-10-17T21:30:13Z

I've been tracing the stringmime calls, and it ends up in line 971 in Gadfly.jl, which then moves on to compose. The following calls in Compose's precompile might be useful:

svg = SVGJS(IOBuffer(), Compose.default_graphic_width,
                       Compose.default_graphic_height, false)
draw(svg, container::Compose.Container)
writemime(STDOUT, MIME("text/html"), svg)

What I don't know is what container should be in the second line above. From gadfly, it is called with render(p::Plot) which creates the Compose.container . But obviously in compose we cannot use Gadfly objects, we should create the container directly in compose.

PS: @tlnagy, for the record, you second call should be stringmime(MIME("text/html"), plot(x=1:5, y=1:5, Geom.line)), but as you and Mike say, it does not help.

ViralBShah · 2016-10-17T22:02:13Z

I had carried out some of these experiments before and reached the same conclusions. FWIW, we used to have much faster plots on juliabox with julia 0.3, when Gadfly was built into the Julia system image.

tlnagy · 2016-10-17T22:33:01Z

Make sure to instantiate the mime type. There's a neater string macro as well.

Ah yeah, thanks.

What I don't know is what container should be in the second line above. From gadfly, it is called with render(p::Plot) which creates the Compose.container . But obviously in compose we cannot use Gadfly objects, we should create the container directly in compose.

The key might be in there somewhere.

I had carried out some of these experiments before and reached the same conclusions. FWIW, we used to have much faster plots on juliabox with julia 0.3, when Gadfly was built into the Julia system image.

It must be something with how precompilation is wired up across Gadfly and Compose because once the first plot is generated, it's pretty quick.

timholy · 2017-03-20T23:31:19Z

The old precompile.jl scripts were generated with SnoopCompile, but they might need updating if the internal architecture of Gadfly/Compose has changed. That said, it still can't do everything because:

precompilation doesn't cache machine code, only type-inferred code;
package precompilation doesn't work across module boundaries. Since Gadfly depends on a lot of other packages, any function that takes arguments that involve more than one module (e.g., push! from Base and SomeComposeObject from Compose) won't be cached even in type-inferred form.

Only the userimg.jl trick described in the SnoopCompile docs can overcome these limitations, but it has its own disadvantages.

For folks who dislike the overhead that precompile files add to recompiling Gadfly, don't forget about julia's --compilecache startup option. Nice for Gadfly developers 😄.

tlnagy · 2017-03-21T00:54:38Z

I think I managed to track down the problem back when looking in #921. It was never the rendering in Compose or Gadfly that was slow, it was always the moment it had to actually generate plot and get the browser to open it.

bjarthur · 2017-03-21T11:56:51Z

precompilation across module boundaries seems like a generally useful thing, and a good solution for Gadfly's first-time-to-plot latency. would that be hard to implement?

timholy · 2017-03-21T13:12:35Z

I haven't really looked. I suspect the crucial code is Julia's src/dump.c file.

tlnagy · 2017-03-21T17:23:41Z

@bjarthur I remember trying to pin down whether it was being caused by the separation between Gadfly and Compose, but I wasn't able to pin it down exactly.

@timholy Why do you think that's the culprit?

ViralBShah · 2017-03-21T17:26:27Z

Cc @vtjnash

timholy · 2017-03-21T19:30:46Z

@timholy Why do you think that's the culprit?

I don't, that's just a hunch. These are the only two limitations of precompilation that I know about.

timholy · 2017-03-22T12:24:26Z

OK, with this gist I can demonstrate a small penalty due to having multiple modules:

julia> include("twocalls.jl")
testscript (generic function with 1 method)

julia> onemodule(10^3)

julia> twomodules(10^3)

julia> testscript("/tmp/runtests.jl", 10^3)

Now go to /tmp and check out A.jl, B.jl, C.jl, and runtests.jl to see what this is all about. Then from /tmp start the REPL and do this:

julia> push!(LOAD_PATH, pwd())
3-element Array{String,1}:
 "/home/tim/src/julia-0.5/usr/local/share/julia/site/v0.5"
 "/home/tim/src/julia-0.5/usr/share/julia/site/v0.5"      
 "/tmp"                                                   

julia> using A
INFO: Recompiling stale cache file /home/tim/.julia/lib/v0.5/A.ji for module A.

julia> include("runtests.jl")
runfoo (generic function with 1 method)

julia> @time runfoo()
  2.529762 seconds (316.71 k allocations: 13.272 MB, 0.40% gc time)
336342000

Restart julia and do it again, but this time with using B instead of using A. I get this:

julia> @time runfoo()
  2.976062 seconds (971.97 k allocations: 45.177 MB, 0.73% gc time)
336342000

Not a huge difference, but it's something. A number of issues filed against Julia have demonstrated that some functions have much longer inference time than others, so one shouldn't take this ratio as being a universal truth.

For Gadfly, the best thing would be to profile the time to display the first plot, and see where the time is going (make sure you use C=true so you can see time needed for LLVM to generate machine code).

protogeezer · 2017-03-27T17:22:15Z

Is there a way to use the Julia static ahead of time (AOT) compilation feature to blitz the long first plot delay? Or even better, to make it possible to debug Julia code with lldb?

bjarthur · 2017-04-20T19:53:59Z

i can't make sense of @profile's gibberish, but this snippet accounts for half the time to simply plot(y=[1,2,3],Geom.point)

                50 ....julia/v0.6/Gadfly/src/Gadfly.jl:393; plot(::Void, ::Dict{Symbol,Any}, ::DataType)
                 48 ...ulia/v0.6/Gadfly/src/mapping.jl:307; evalmapping!(::Dict{Symbol,Any}, ::Void, ::Gadf...
                  48 ...rc/julia/src/./julia_internal.h:347; jl_call_method_internal
                   44 ...rc/julia/src/./julia_internal.h:319; jl_compile_method_internal
                    44 ...hurb/src/julia/src/codegen.cpp:1502; jl_generate_fptr
                     44 ...urb/src/julia/src/codegen.cpp:1405; getAddressForFunction
                      44 ...b/src/julia/src/jitlayers.cpp:821; jl_finalize_function
                       44 ...b/src/julia/src/jitlayers.cpp:810; jl_add_to_ee
                        44 ...b/src/julia/src/jitlayers.cpp:586; addModule
                         43 ...onEngine/Orc/IRCompileLayer.h:73; addModuleSet<llvm::SmallVector<std::__1::uni...
                          43 ..../include/c++/v1/functional:1817; operator()
                           43 ..../include/c++/v1/functional:1437; operator()
                            43 ...de/c++/v1/__functional_base:437; __call<(lambda at /Users/arthurb/src/juli...
                             43 ...de/c++/v1/__functional_base:416; __invoke<(lambda at /Users/arthurb/src/ju...
                              43 ...rc/julia/src/jitlayers.cpp:460; operator()
                               43 ...julia/usr/lib/libLLVM.dylib:?; _ZN4llvm6legacy15PassManagerImpl3runERNS_...
                                39 ...ulia/usr/lib/libLLVM.dylib:?; _ZN4llvm13FPPassManager11runOnModuleERNS...
                                 39 ...ulia/usr/lib/libLLVM.dylib:?; _ZN4llvm13FPPassManager13runOnFunctionE...
                                  14 ...lia/usr/lib/libLLVM.dylib:?; _ZN4llvm19MachineFunctionPass13runOnFun...
                                   8 ...lia/usr/lib/libLLVM.dylib:?; _ZN12_GLOBAL__N_115X86DAGToDAGISel20run...
                                    8 ...lia/usr/lib/libLLVM.dylib:?; _ZN4llvm16SelectionDAGISel20runOnMachi...
                                     8 ...lia/usr/lib/libLLVM.dylib:?; _ZN4llvm16SelectionDAGISel20SelectAllB...
                                      7 ...ia/usr/lib/libLLVM.dylib:?; _ZN4llvm16SelectionDAGISel17CodeGenAn...

what i really don't understand is why evalmapping! can't be precompiled. at least, i assume that's what the return value of false means.

julia> precompile(Gadfly.evalmapping!, (Dict, Any, Gadfly.Data))
false

mkitti · 2022-09-26T05:54:48Z

what i really don't understand is why evalmapping! can't be precompiled. at least, i assume that's what the return value of false means.
julia> precompile(Gadfly.evalmapping!, (Dict, Any, Gadfly.Data))
false

This is very old, but isn't the issue here that the types being provided in the tuple are not concrete? The Dict needs parameters and Any is not concrete. Something like the following would work. I'm also sensing the need for a @nospecialize on the second argument.

julia> precompile(Gadfly.evalmapping!, (Dict{Symbol, Any}, Nothing, Gadfly.Data))
true

ViralBShah changed the title ~~Time to first plot in Gadfly is very slow.~~ Time to first plot in Gadfly is very slow even after Gadfly has been precompiled. Oct 16, 2016

tlnagy mentioned this issue Oct 16, 2016

Gadfly precompilation is very slow #919

Closed

tlnagy added the enhancement label Oct 16, 2016

bjarthur mentioned this issue Feb 22, 2017

strip out old precompilation code #958

Merged

glycerine mentioned this issue Dec 22, 2017

Gadfly load time regression from 0.5 to 0.6. JuliaLang/julia#25254

Closed

bjarthur mentioned this issue Apr 27, 2019

Use snoopcompile to more aggressively precompile Gadfly #1280

Open

6 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Time to first plot in Gadfly is very slow even after Gadfly has been precompiled. #921

Time to first plot in Gadfly is very slow even after Gadfly has been precompiled. #921

ViralBShah commented Oct 16, 2016

ViralBShah commented Oct 16, 2016

tlnagy commented Oct 16, 2016

ViralBShah commented Oct 17, 2016

tlnagy commented Oct 17, 2016 •

edited

MikeInnes commented Oct 17, 2016

tlnagy commented Oct 17, 2016

MikeInnes commented Oct 17, 2016

aviks commented Oct 17, 2016

ViralBShah commented Oct 17, 2016 •

edited

tlnagy commented Oct 17, 2016

timholy commented Mar 20, 2017

tlnagy commented Mar 21, 2017

bjarthur commented Mar 21, 2017

timholy commented Mar 21, 2017

tlnagy commented Mar 21, 2017

ViralBShah commented Mar 21, 2017

timholy commented Mar 21, 2017

timholy commented Mar 22, 2017

protogeezer commented Mar 27, 2017 via email

bjarthur commented Apr 20, 2017

mkitti commented Sep 26, 2022

Time to first plot in Gadfly is very slow even after Gadfly has been precompiled. #921

Time to first plot in Gadfly is very slow even after Gadfly has been precompiled. #921

Comments

ViralBShah commented Oct 16, 2016

ViralBShah commented Oct 16, 2016

tlnagy commented Oct 16, 2016

ViralBShah commented Oct 17, 2016

tlnagy commented Oct 17, 2016 • edited

MikeInnes commented Oct 17, 2016

tlnagy commented Oct 17, 2016

MikeInnes commented Oct 17, 2016

aviks commented Oct 17, 2016

ViralBShah commented Oct 17, 2016 • edited

tlnagy commented Oct 17, 2016

timholy commented Mar 20, 2017

tlnagy commented Mar 21, 2017

bjarthur commented Mar 21, 2017

timholy commented Mar 21, 2017

tlnagy commented Mar 21, 2017

ViralBShah commented Mar 21, 2017

timholy commented Mar 21, 2017

timholy commented Mar 22, 2017

protogeezer commented Mar 27, 2017 via email

bjarthur commented Apr 20, 2017

mkitti commented Sep 26, 2022

tlnagy commented Oct 17, 2016 •

edited

ViralBShah commented Oct 17, 2016 •

edited