GiovineItalia / Gadfly.jl

Crafty statistical graphics for Julia.
http://gadflyjl.org/stable/
Other
1.9k stars 251 forks source link

Gadfly first-plot profiling results #1275

Open non-Jedi opened 5 years ago

non-Jedi commented 5 years ago

I got curious about "time to first plot" and did some profiling to see where most of the problem was coming from. I thought it might be useful to share the results here for other's reference so that you don't have to figure out the proper incantations of Profile yourself. The approximate recipe for reproducing this is:

using Gadfly, Profile

x = collect(1:2000)
y = rand(2000)
p = plot(x=x, y=y, Geom.line);
Profile.init(10000000, 0.005)
@profile draw(SVG("test.svg", 4cm, 4cm), p)

Here's the results of the profiling in tree-view:

8277 /home/adam/repos/Gadfly.jl/src/Gadfly.jl:851; draw(::SVG, ::Plot)
 1982 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:334; draw
  1965 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
   1791 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
    1463 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:368; drawpart(::SVG, ::Compose.Table, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
     1428 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
      309 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:481; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
       275 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:481; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
        192 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
      928 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
       473 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:364; drawpart(::SVG, ::Compose.AdhocContainerPromise, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
        473 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:281; realize(::Compose.AdhocContainerPromise, ::Compose.ParentDrawContext)
       451 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:368; drawpart(::SVG, ::Compose.AdhocContainerPromise, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
        113 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:433; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
        103 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:440; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
        101 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:455; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
 2041 /home/adam/repos/Gadfly.jl/src/Gadfly.jl:742; render(::Plot)
  1055 /home/adam/repos/Gadfly.jl/src/Gadfly.jl:649; render_prepare(::Plot)
   1025 /home/adam/repos/Gadfly.jl/src/scale.jl:33; apply_scales(::IterTools.Distinct{Base.ValueIterator{Dict{Symbol,Gadfly.ScaleElement}},Gadfly.ScaleElement}, ::Gadfly.Data)
    998 /home/adam/repos/Gadfly.jl/src/scale.jl:23; apply_scales(::IterTools.Distinct{Base.ValueIterator{Dict{Symbol,Gadfly.ScaleElement}},Gadfly.ScaleElement}, ::Array{Gadfly.Aesthetics,1}, ::Gadfly.Data)
     453 /home/adam/repos/Gadfly.jl/src/scale.jl:512; apply_scale(::Gadfly.Scale.DiscreteColorScale, ::Array{Gadfly.Aesthetics,1}, ::Gadfly.Data)
     118 /home/adam/repos/Gadfly.jl/src/scale.jl:514; apply_scale(::Gadfly.Scale.DiscreteColorScale, ::Array{Gadfly.Aesthetics,1}, ::Gadfly.Data)
  436  /home/adam/repos/Gadfly.jl/src/Gadfly.jl:691; render_prepare(::Plot)
   436 /home/adam/repos/Gadfly.jl/src/statistics.jl:34; apply_statistics(::Array{Gadfly.StatisticElement,1}, ::Dict{Symbol,Gadfly.ScaleElement}, ::Gadfly.Coord.Cartesian, ::Gadfly.Aesthetics)
 4222 /home/adam/repos/Gadfly.jl/src/Gadfly.jl:746; render(::Plot)
  4047 /home/adam/repos/Gadfly.jl/src/Gadfly.jl:800; render_prepared(::Plot, ::Gadfly.Coord.Cartesian, ::Gadfly.Aesthetics, ::Array{Gadfly.Aesthetics,1}, ::Array{Array{Gadfly.StatisticElement,1},1}, ::Array{Array{Gadfly.Aesthetics,1},1}, ::Array{Array{Gadfly.Data,1},1}, ::Dict{Symbol,Gadfly.ScaleElement}, ::Array{Gadfly.GuideElement,1})
   127  /home/adam/repos/Gadfly.jl/src/Gadfly.jl:800; #render_prepared#99(::Bool, ::Bool, ::Function, ::Plot, ::Gadfly.Coord.Cartesian, ::Gadfly.Aesthetics, ::Array{Gadfly.Aesthetics,1}, ::Array{Array{Gadfly.StatisticElement,1},1}, ::Array{Array{Gadfly.Aesthetics,1},1}, ::Array{Array{Gadfly.Data,1},1}, ::Dict{Symbol,Gadfly.ScaleElement}...
   1815 /home/adam/repos/Gadfly.jl/src/Gadfly.jl:811; #render_prepared#99(::Bool, ::Bool, ::Function, ::Plot, ::Gadfly.Coord.Cartesian, ::Gadfly.Aesthetics, ::Array{Gadfly.Aesthetics,1}, ::Array{Array{Gadfly.StatisticElement,1},1}, ::Array{Array{Gadfly.Aesthetics,1},1}, ::Array{Array{Gadfly.Data,1},1}, ::Dict{Symbol,Gadfly.ScaleElement}...
    1308 ./generator.jl:47; collect(::Base.Generator{Base.Iterators.Zip{Tuple{Array{Layer,1},Array{Gadfly.Aesthetics,1},Array{Array{Gadfly.Aesthetics,1},1},Array{Array{Gadfly.Data,1},1},Array{Theme,1}}},getfield(Gadfly, Symbol("##100#101")){Dict{Symbol,Gadfly.ScaleElement}}})
     1308 ./none:0; (::getfield(Gadfly, Symbol("##100#101")){Dict{Symbol,Gadfly.ScaleElement}})(::Tuple{Layer,Gadfly.Aesthetics,Array{Gadfly.Aesthetics,1},Array{Gadfly.Data,1},Theme})
      757 /home/adam/repos/Gadfly.jl/src/geometry.jl:46; render(::Gadfly.Geom.LineGeometry, ::Theme, ::Gadfly.Aesthetics, ::Array{Gadfly.Aesthetics,1}, ::Array{Gadfly.Data,1}, ::Dict{Symbol,Gadfly.ScaleElement})
       113 /home/adam/repos/Gadfly.jl/src/geom/line.jl:159; render(::Gadfly.Geom.LineGeometry, ::Theme, ::Gadfly.Aesthetics)
   1485 /home/adam/repos/Gadfly.jl/src/Gadfly.jl:820; #render_prepared#99(::Bool, ::Bool, ::Function, ::Plot, ::Gadfly.Coord.Cartesian, ::Gadfly.Aesthetics, ::Array{Gadfly.Aesthetics,1}, ::Array{Array{Gadfly.StatisticElement,1},1}, ::Array{Array{Gadfly.Aesthetics,1},1}, ::Array{Array{Gadfly.Data,1},1}, ::Dict{Symbol,Gadfly.ScaleElement}...
    338 /home/adam/repos/Gadfly.jl/src/guide.jl:141; render(::Gadfly.Guide.QuestionMark, ::Theme, ::Gadfly.Aesthetics, ::Bool)
     110 /home/adam/repos/Gadfly.jl/src/guide.jl:69; render(::Gadfly.Guide.HelpScreen, ::Theme, ::Gadfly.Aesthetics)
     111 /home/adam/repos/Gadfly.jl/src/guide.jl:76; render(::Gadfly.Guide.HelpScreen, ::Theme, ::Gadfly.Aesthetics)
     111 /home/adam/repos/Gadfly.jl/src/guide.jl:78; render(::Gadfly.Guide.HelpScreen, ::Theme, ::Gadfly.Aesthetics)
    105 /home/adam/repos/Gadfly.jl/src/guide.jl:610; render(::Gadfly.Guide.XTicks, ::Theme, ::Gadfly.Aesthetics, ::Bool)
   301  /home/adam/repos/Gadfly.jl/src/Gadfly.jl:826; #render_prepared#99(::Bool, ::Bool, ::Function, ::Plot, ::Gadfly.Coord.Cartesian, ::Gadfly.Aesthetics, ::Array{Gadfly.Aesthetics,1}, ::Array{Array{Gadfly.StatisticElement,1},1}, ::Array{Array{Gadfly.Aesthetics,1},1}, ::Array{Array{Gadfly.Data,1},1}, ::Dict{Symbol,Gadfly.ScaleElement}...

The big thing that jumped out to me from this is that during the "first plot", over 75% of time (this plot took roughly 50 seconds to finish) is spent in Gadfly versus only ~25% spent in Compose. So it isn't actually drawing the plot that's taking long precompile times but all the work Gadfly does in the various render functions before sending to Compose. So that's the place to start investigating.

For contrast, here's the profile dump for subsequent calls to plot:

1119 /home/adam/repos/Gadfly.jl/src/Gadfly.jl:851; draw
 772 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:334; draw
  772 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
   771 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
    768 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:368; drawpart(::SVG, ::Compose.Table, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
     768 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
      165 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:481; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
       152 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
        151 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
         151 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:481; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
          151 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
           76 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:440; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
            76 /home/adam/.julia/packages/Compose/aVZwV/src/form.jl:22; resolve(::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}}, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Compose.IdentityTransform, ::Compose.Form{Compose.LinePrimi...
             76 ./array.jl:606; collect(::Base.Generator{Array{Compose.LinePrimitive,1},getfield(Compose, Symbol("##9#10")){Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}},Compose.UnitBox{Float64,Float64...
              76 ./generator.jl:47; iterate
               76 ./none:0; (::getfield(Compose, Symbol("##9#10")){Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}},Compose.UnitBox{Float64,Float64,Float64,Float64},Compose.IdentityTransform})(::Compo...
                76 /home/adam/.julia/packages/Compose/aVZwV/src/form.jl:513; resolve(::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}}, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Compose.IdentityTransform, ::Compose.LinePrimitive{Tuple...
                 70 /home/adam/.julia/packages/Compose/aVZwV/src/measure.jl:281; resolve(::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}}, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Compose.IdentityTransform, ::Tuple{Measures.Length{:cx,I...
           74 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:455; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
            74 /home/adam/.julia/packages/Compose/aVZwV/src/svg.jl:736; draw(::SVG, ::Compose.Form{Compose.LinePrimitive{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}}})
      601 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:487; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
       355 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:364; drawpart(::SVG, ::Compose.AdhocContainerPromise, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float...
        355 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:281; realize(::Compose.AdhocContainerPromise, ::Compose.ParentDrawContext)
         104 /home/adam/repos/Gadfly.jl/src/guide.jl:947; (::getfield(Gadfly.Guide, Symbol("##69#71")){Gadfly.Guide.XLabel,Theme,Measures.Length{:mm,Float64}})(::Compose.ParentDrawContext)
       246 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:368; drawpart(::SVG, ::Compose.AdhocContainerPromise, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float...
        228 /home/adam/.julia/packages/Compose/aVZwV/src/container.jl:440; drawpart(::SVG, ::Compose.Context, ::Compose.IdentityTransform, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}})
         66 /home/adam/.julia/packages/Compose/aVZwV/src/form.jl:22; resolve(::Measures.BoundingBox{Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}}, ::Compose.UnitBox{Float64,Float64,Float64,Float64}, ::Compose.IdentityTransform, ::Compose.Form{Compose.TextPrimiti...
          66 ./array.jl:611; collect(::Base.Generator{Array{Compose.TextPrimitive{Tuple{Measures.Length{:w,Float64},Measures.Length{:mm,Float64}},Compose.Rotation{Tuple{Measures.Length{:w,Float64},Measures.Length{:mm,Float64}}},Tuple{Measures.Length{:mm,Float64},Measures.Length{:mm,Float64}}},1},getfield(...
 285 /home/adam/repos/Gadfly.jl/src/Gadfly.jl:746; render(::Plot)
  285 /home/adam/repos/Gadfly.jl/src/Gadfly.jl:800; render_prepared(::Plot, ::Gadfly.Coord.Cartesian, ::Gadfly.Aesthetics, ::Array{Gadfly.Aesthetics,1}, ::Array{Array{Gadfly.StatisticElement,1},1}, ::Array{Array{Gadfly.Aesthetics,1},1}, ::Array{Array{Gadfly.Data,1},1}, ::Dict{Symbol,Gadfly.ScaleElement}, ::Array{Gadfly.GuideElement...
   265 /home/adam/repos/Gadfly.jl/src/Gadfly.jl:820; #render_prepared#99(::Bool, ::Bool, ::Function, ::Plot, ::Gadfly.Coord.Cartesian, ::Gadfly.Aesthetics, ::Array{Gadfly.Aesthetics,1}, ::Array{Array{Gadfly.StatisticElement,1},1}, ::Array{Array{Gadfly.Aesthetics,1},1}, ::Array{Array{Gadfly.Data,1},1}, ::Dict{Symbol,Gadfly.ScaleElem...
    88  /home/adam/repos/Gadfly.jl/src/guide.jl:141; render(::Gadfly.Guide.HelpScreen, ::Theme, ::Gadfly.Aesthetics, ::Bool)
     88 /home/adam/repos/Gadfly.jl/src/guide.jl:69; render(::Gadfly.Guide.HelpScreen, ::Theme, ::Gadfly.Aesthetics)
      88 /home/adam/.julia/packages/Colors/4hvzi/src/colormaps.jl:85; distinguishable_colors(::Int64, ::ColorTypes.RGB{FixedPointNumbers.Normed{UInt8,8}})
       88 /home/adam/.julia/packages/Colors/4hvzi/src/colormaps.jl:85; #distinguishable_colors#7(::Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),Tuple{}}}, ::Function, ::Int64, ::ColorTypes.RGB{FixedPointNumbers.Normed{UInt8,8}})
        88 /home/adam/.julia/packages/Colors/4hvzi/src/colormaps.jl:39; distinguishable_colors
    166 /home/adam/repos/Gadfly.jl/src/guide.jl:639; render(::Gadfly.Guide.XTicks, ::Theme, ::Gadfly.Aesthetics, ::Bool)
     118 /home/adam/.julia/packages/Compose/aVZwV/src/fontfallback.jl:122; text_extents(::String, ::Measures.Length{:mm,Float64}, ::String, ::Vararg{String,N} where N)
      85 ./iterators.jl:138; iterate

It's the reverse of the first-plot situation: almost 70% of time is spent in Compose with relatively little in Gadfly.

When I get a chance, I'll probably do a bit more digging on this subject, but like I said, I thought this might be useful or spark some thoughts for others in the meantime. It's unclear to me how much of this first-call latency can be mitigated by package developers, but it's probably worth a shot.

bjarthur commented 5 years ago

there's also PackageCompiler. i'm close to merging instructions as to how to use it with Gadfly.

tlnagy commented 5 years ago

My hunch is that this line is contributing a lot:

     1308 ./none:0; (::getfield(Gadfly, Symbol("##100#101")){Dict{Symbol,Gadfly.ScaleElement}})(::Tuple{Layer,Gadfly.Aesthetics,Array{Gadfly.Aesthetics,1},Array{Gadfly.Data,1},Theme})

I believe getfield calls are pretty bad

Mattriks commented 5 years ago

Here's another view into Gadfly:

function plot_min()
# function render_prepare    
    @time datas = Gadfly.Data(x=1:10, y=rand(10), xend=1:10, yend=zeros(10))
@time scales=Dict{Symbol,Gadfly.ScaleElement}(:x=>Scale.x_continuous(), :y=>Scale.y_continuous())
    @time aes = Scale.apply_scales(collect(values(scales)), datas)
    @time coord = Coord.cartesian()
    @time stats = Gadfly.StatisticElement[Stat.xticks(), Stat.yticks()]
    @time Stat.apply_statistics(stats, scales, coord, aes[1])

# function render_prepared
    @time plot_context = Coord.apply_coordinate(coord, aes, scales)
    @time layer_themes = [Theme(default_color="green"), Theme(default_color="orange")]
    @time geom_ctxs = render.([Geom.point(), Geom.hair()], layer_themes, aes)
    @time guide_ctxs = render.([Guide.xticks(), Guide.yticks()], [Theme()], aes)
    @time compose!(plot_context, (context(), geom_ctxs...))
  @time tbl =  Guide.layout_guides(plot_context, coord, Theme(), [x[1] for x in  guide_ctxs]...)

    @time p = compose!(context(), tbl)
    @time draw(PNG(), p)
    @time draw(SVG(), p)
    return nothing
end
julia> plot_min()
 0.000017 seconds (7 allocations: 1.266 KiB)
  0.056249 seconds (18.63 k allocations: 970.111 KiB, 39.13% gc time)
  0.420187 seconds (364.51 k allocations: 20.095 MiB)
  0.000002 seconds (3 allocations: 352 bytes)
  0.000000 seconds (3 allocations: 224 bytes)
  1.856495 seconds (1.21 M allocations: 62.480 MiB, 2.68% gc time)

  0.230436 seconds (184.17 k allocations: 9.604 MiB, 6.87% gc time)
  0.763589 seconds (48.97 k allocations: 2.429 MiB)
  4.916489 seconds (6.29 M allocations: 325.060 MiB, 5.63% gc time)
  3.684096 seconds (3.50 M allocations: 176.035 MiB, 3.75% gc time)
  0.009549 seconds (1.78 k allocations: 92.083 KiB)
 1.432211 seconds (974.65 k allocations: 50.617 MiB, 2.53% gc time)

  0.000000 seconds (2 allocations: 176 bytes)
 11.263422 seconds (11.94 M allocations: 615.439 MiB, 4.89% gc time)
  5.497432 seconds (8.27 M allocations: 419.332 MiB, 3.10% gc time)
non-Jedi commented 5 years ago

I got a marginal speedup (5%-10%) in first-plot compile by going in and removing the splatting from a lot of internal methods. I'll pretty that up into a PR soon. To be honest, I thought the benefit there would be bigger based on what I was seeing in the profiling results. The next thing I'm gonna try is seeing if I can change some of the internal structs that don't have concretely typed fields to have strictly concrete fields; might see a speedup there I think.