Latency regression in Plots on master vs 1.7

[KristofferC]

1.7:

julia> @time using Plots
  2.311376 seconds (7.10 M allocations: 490.159 MiB, 2.82% gc time, 0.35% compilation time)

julia> @time (p = plot(rand(2,2)); display(p));
  6.417196 seconds (18.23 M allocations: 959.720 MiB, 3.93% gc time, 17.02% compilation time)

master:

julia> @time using Plots
  3.946437 seconds (9.13 M allocations: 622.219 MiB, 4.27% gc time, 1.18% compilation time)

julia> @time (p = plot(rand(2,2)); display(p));
  8.140353 seconds (18.87 M allocations: 1001.987 MiB, 1.61% gc time, 17.00% compilation time)

I haven't looked deeply into it yet.

[aviatesk]

From sysimg log, there seems to be significant difference between precompiled statements

release/v1.7

    JULIA usr/lib/julia/sys-o.a
Generating REPL precompile statements... 31/31
Executing precompile statements... 1395/1431
Precompilation complete. Summary:
Total ─────── 105.469442 seconds
Generation ──  79.721119 seconds 75.5869%
Execution ───  25.748323 seconds 24.4131%

master

    JULIA usr/lib/julia/sys-o.a
Generating REPL precompile statements... 31/31
Executing precompile statements... 1244/1276
Precompilation complete. Summary:
Total ───────  98.027579 seconds
Generation ──  74.974410 seconds 76.483%
Execution ───  23.053170 seconds 23.517%

and I guess we need to compile more things at runtime on master ? Haven't bisected what caused this particular regression though.

EDIT: well, there is not much difference between 1.7.0-beta4.1 and master ?

release/v1.7

~/julia3 remotes/origin/release-1.7 aviatesk@amdci2 7s
❯ ./usr/bin/julia -e '@time using Plots; @time plot(rand(10,3))'
  3.693188 seconds (7.44 M allocations: 510.916 MiB, 3.79% gc time, 0.24% compilation time)
  2.870833 seconds (3.60 M allocations: 199.335 MiB, 7.50% gc time, 56.30% compilation time)

master

~/julia avi/noinfer ⇣⇡ aviatesk@amdci2 7s
❯ ./usr/bin/julia -e '@time using Plots; @time plot(rand(10,3))'
  3.460878 seconds (7.19 M allocations: 493.561 MiB, 5.72% gc time, 1.23% compilation time)
  2.995208 seconds (3.49 M allocations: 196.758 MiB, 9.84% gc time, 57.56% compilation time)

[timholy]

Plots is a tough case because the most effective way to be cross-version and cross-platform is to use

if ccall(:jl_generating_output, Cint, ()) == 1
    while false; end   # disable the interpreter
    do_work(small_dataset)
end

rather than

if ccall(:jl_generating_output, Cint, ()) == 1
    precompile(do_work, (DataSetType,))
end

but plotting has side effects.Still, they should probably try to transition to this style wherever possible. Currently they rely on the bot to generate precompiles.

[KristofferC]

EDIT: well, there is not much difference between 1.7.0-beta4.1 and master ?

Yes, looks like something regressed vs beta3?

beta3:

julia> @time using Plots
  3.277906 seconds (7.42 M allocations: 511.464 MiB, 9.06% gc time, 0.20% compilation time)

julia> @time (p = plot(rand(2,2)); display(p));
  7.475758 seconds (18.31 M allocations: 962.836 MiB, 2.53% gc time, 15.59% compilation time)

on #41781:

julia> @time using Plots
  4.682400 seconds (8.93 M allocations: 610.531 MiB, 7.02% gc time, 0.16% compilation time)

julia> @time (p = plot(rand(2,2)); display(p));
  9.137335 seconds (19.63 M allocations: 1.005 GiB, 2.10% gc time, 16.63% compilation time)

Should be fairly quick to bisect perhaps.

[JeffBezanson]

I get:

1.7.0-rc1:

julia> @time using Plots
  4.155797 seconds (8.16 M allocations: 571.039 MiB, 8.09% gc time, 0.34% compilation time)

julia> @time display(plot(rand(10)))
  6.991758 seconds (10.62 M allocations: 569.403 MiB, 1.73% gc time)

master:

julia> @time using Plots
  6.922687 seconds (12.16 M allocations: 778.810 MiB, 5.00% gc time, 1.01% compilation time)

julia> @time display(plot(rand(10)))
 10.923829 seconds (22.90 M allocations: 1.203 GiB, 2.35% gc time)

[aviatesk]

I just found the throw deopt can be broken on the master (due to #42149). I will post an issue on this later and also benchmark this reverting that commit.

[aviatesk]

So there are two levels of TTFP regression...:

• between 1.7-beta3 and 1.7-rc1
• 1.7-rc1 and master

---

I filed an issue around throw block deoptimization (#42258), which I thought can be a trigger of the regression between 1.7-rc1 and master.
I tried the plot benchmark with reverting #42149 that can be pretty confused by the issue, but it seems like the regression between master and v1.7-rc1 is not caused by that:

master

~/julia master aviatesk@amdci2 11s
❯ ./usr/bin/julia -e '@time using Plots; @time plot(rand(10,3))'
  7.265401 seconds (12.46 M allocations: 793.437 MiB, 5.08% gc time, 0.65% compilation time)
  2.661832 seconds (3.55 M allocations: 196.283 MiB, 2.25% gc time)

with reverting #42149

~/julia3 master ⇡ aviatesk@amdci2 10m 7s
❯ ./usr/bin/julia -e '@time using Plots; @time plot(rand(10,3))'
  7.294589 seconds (12.44 M allocations: 791.542 MiB, 5.15% gc time, 0.63% compilation time)
  2.622218 seconds (3.64 M allocations: 204.145 MiB, 1.88% gc time)

[KristofferC]

Tried again: I get:

julia> @time using Plots
# 1.6.2:
  2.795078 seconds (8.13 M allocations: 564.960 MiB, 3.26% gc time, 0.10% compilation time)
# 1.7.0-rc1:
  4.379164 seconds (10.48 M allocations: 713.449 MiB, 5.69% gc time, 0.15% compilation time)
# master:
  7.175294 seconds (16.00 M allocations: 1018.494 MiB, 3.80% gc time, 0.17% compilation time)

julia> @time display(plot(rand(10)))
# 1.6.2:
  6.755702 seconds (18.10 M allocations: 1.013 GiB, 4.01% gc time, 15.37% compilation time)
# 1.7.0-rc1:
  8.278466 seconds (18.85 M allocations: 1001.208 MiB, 1.95% gc time)
# mater:
 10.549896 seconds (25.17 M allocations: 1.321 GiB, 1.90% gc time, 13.70% compilation time)

So 1.7 is bad and master is really bad. 2x regression in using seems milestone worthy. I'll try to bisect it.

[KristofferC]

From sysimg log, there seems to be significant difference between precompiled statements

@aviatesk, that's from #41898

[aviatesk]

So 1.7 is bad and master is really bad.

😱 okay, I will also try to bisect it (I think currently we don't have a solid way to define a latency regression)

[KristofferC]

I checked out 1.6.2 locally and get:

julia> @time using Plots
  5.467579 seconds (10.95 M allocations: 743.108 MiB, 4.75% gc time, 0.13% compilation time)

julia> VERSION
v"1.6.2"

And if I use the released version downloaded from the website:

julia> @time using Plots
  2.821719 seconds (7.97 M allocations: 554.232 MiB, 7.47% gc time, 0.15% compilation time)

julia> VERSION
v"1.6.2"

Hard to bisect when the same Julia version can give so dramatically different results... I even cleaned out .julia/compiled in between.

Edit: I need to check when I'm back at the computer that I am not running with assertions on or something like that.

[vchuravy]

Hard to bisect when the same Julia version can give so dramatically different results...

Do you have any Make.user flags set?