performance regression

[mlubin]

d536d66 caused a performance regression in speed2.jl:

before:

PMEDIAN BUILD MIN=0.203871825  MED=0.335640704
PMEDIAN INTRN MIN=0.232986952  MED=0.315446562
CONT5 BUILD   MIN=0.13317529  MED=0.141698087
CONT5 INTRN   MIN=0.305028515  MED=0.35890098

after:

PMEDIAN BUILD MIN=0.473440865  MED=0.70468973
PMEDIAN INTRN MIN=0.267753664  MED=0.392924117
CONT5 BUILD   MIN=0.400080277  MED=0.488471479
CONT5 INTRN   MIN=0.272141025  MED=0.356078075

This can be fixed by being a bit more careful about explicit AffExpr objects inside expressions, and then we can return to the mutating behavior.

[mlubin]

I'm having trouble reproducing this now. Maybe I did my "before" timings with julia 0.3, but I don't see any changes before and after d536d66.

[joehuchette]

(Hopefully) we can close this?

[mlubin]

There's still an apparent performance regression compared with the times reported in #271. We should leave this open to investigate.

[mlubin]

Saw a good improvement from the new GC:

PMEDIAN BUILD MIN=0.275633896  MED=0.465595191
PMEDIAN INTRN MIN=0.33398638  MED=0.362346971
CONT5 BUILD   MIN=0.231607576  MED=0.30835695
CONT5 INTRN   MIN=0.282945696  MED=0.310390551

[mlubin]

Was going to close this, but just reran speed2.jl and got pretty poor results:

PMEDIAN BUILD MIN=1.10124614  MED=1.285939783
PMEDIAN INTRN MIN=0.898177808  MED=0.983338674
CONT5 BUILD   MIN=0.450968003  MED=0.785816698
CONT5 INTRN   MIN=0.970375278  MED=1.132538846

[joehuchette]

bisect?

[mlubin]

Yeah, won't be too fun

[joehuchette]

For the record, I'm not seeing this on master v. release-0.9 v release-0.8:

master:
PMEDIAN BUILD MIN=0.521984954  MED=0.571531506
PMEDIAN INTRN MIN=0.538392751  MED=0.5734822
CONT5 BUILD   MIN=0.164358311  MED=0.360121545
CONT5 INTRN   MIN=0.478522753  MED=0.542167845

release-0.9:
PMEDIAN BUILD MIN=0.582469984  MED=0.652893546
PMEDIAN INTRN MIN=0.584015656  MED=0.672731572
CONT5 BUILD   MIN=0.167540997  MED=0.389436965
CONT5 INTRN   MIN=0.45115562  MED=0.532329719

release-0.8:
PMEDIAN BUILD MIN=0.44847227  MED=0.697972236
PMEDIAN INTRN MIN=0.410742194  MED=0.620489982
CONT5 BUILD   MIN=0.267347092  MED=0.403237269
CONT5 INTRN   MIN=0.435442176  MED=0.457026314

[mlubin]

My computer is easily 2x slower than yours. On release-0.8, julia 0.4 I get:

PMEDIAN BUILD MIN=0.982759163  MED=1.297234528
PMEDIAN INTRN MIN=0.677346677  MED=1.03932382
CONT5 BUILD   MIN=0.412189694  MED=0.733755532
CONT5 INTRN   MIN=0.841223362  MED=0.939774117

On release-0.10, julia 0.3, I get:

PMEDIAN BUILD MIN=0.543185028  MED=0.895558455
PMEDIAN INTRN MIN=0.574605368  MED=0.780449968
CONT5 BUILD   MIN=0.359194598  MED=0.365042909
CONT5 INTRN   MIN=0.833590806  MED=0.968088859

On release-0.10, julia 0.4, I get:

PMEDIAN BUILD MIN=1.184295294  MED=1.262848803
PMEDIAN INTRN MIN=0.903068635  MED=0.957299606
CONT5 BUILD   MIN=0.4391708  MED=0.790355257
CONT5 INTRN   MIN=0.955170052  MED=1.124346703

So 0.4 isn't helping

[IainNZ]

Would be interesting to try one of the other ones, like macro.jl, that don't rely on printing stuff

[mlubin]

This benchmark doesn't have writing, INTRN is the time to build the internal model.

[joehuchette]

❯ julia3 test/perf/speed2.jl                                                 JuMP/git/release-0.10 !
PMEDIAN BUILD MIN=0.322680233  MED=0.81898793
PMEDIAN INTRN MIN=2.168289204  MED=2.729145328
CONT5 BUILD   MIN=0.181007596  MED=0.223112329
CONT5 INTRN   MIN=0.442972168  MED=0.562575775

❯ julia3 test/perf/speed2.jl                                                   JuMP/git/release-0.9
PMEDIAN BUILD MIN=0.340380554  MED=0.482390863
PMEDIAN INTRN MIN=2.036758429  MED=2.08994662
CONT5 BUILD   MIN=0.18786476  MED=0.241229751
CONT5 INTRN   MIN=0.424179478  MED=0.54527626

❯ julia3 test/perf/speed2.jl                                                   JuMP/git/release-0.8
PMEDIAN BUILD MIN=0.327779772  MED=0.439751604
PMEDIAN INTRN MIN=2.140653249  MED=2.185021091
CONT5 BUILD   MIN=0.180096509  MED=0.319829893
CONT5 INTRN   MIN=0.451629904  MED=0.588705272

[joehuchette]

So I'm not seeing anything nearly as dramatic, except for MIN on PMEDIAN BUILD, which is probably just due to the GC change.

[mlubin]

Just ran again today. With JuMP master and 0.4-rc3, I get:

PMEDIAN BUILD MIN=0.601438837  MED=0.740717317
PMEDIAN INTRN MIN=0.292723239  MED=0.50688063
CONT5 BUILD   MIN=0.208948073  MED=0.38849857
CONT5 INTRN   MIN=0.457392275  MED=0.544439037

Maybe my computer was having a bad day. This is much closer to my original "after" times in the original post.

[mlubin]

I guess we're going in circles. Let's close in favor of #42