Time to run N tests grows faster than linear in N: codegen problem?

[dpsanders]

The time to run N tests using FactCheck (which internally uses anonymous functions heavily) grows significantly faster than linear in N, causing long generated test suites to hang.
This apparently is due to #13412 (tested with that commit compared to the previous one; thanks to @andreasnoack). It is approximately linear on 0.4.

I have written a simple file that generates test suites consisting of N tests of the form @fact i-->i:

This gives the following run-times (in seconds!) on 0.5:

[This seems to be faster than power law and slower than exponential growth. Raw data here.]

[IainNZ]

OT, but I liked this so much I ran this on 0.4.1 versus BaseTestNext:
Last 5 FactCheck times: 2.42, 2.63, 2.82, 2.98, 3.13
Last 5 BaseTestNext times: 1.33, 1.47, 1.70, 1.76, 1.94
Don't have a Julia 0.5 build to test BTN on that, but I've add a comment to the linked gist with my code

[IainNZ]

Running it up to 1000 on Julia 0.4.1

[dpsanders]

Thanks, that was useful. Here are the discouraging results for Base.Test on 0.5.
There is definitely an underlying problem floating around.

[StefanKarpinski]

@JeffBezanson: wild guess but could this have to do with the issue you were having with @testset on the jb/functions branch?

[vtjnash]

this appears to be partially related to #15262 (the non-linear behavior of the lowering pass is much stronger than for the rest of the passes)

[JeffBezanson]

I suspect the cl-convert pass. For each local method definition, it scans the whole enclosing function body to look for other definitions with the same name. Should be done by a pass to pre-populate a lookup table.

[JeffBezanson]

Ah, if this happens with lots of comprehensions then it's probably something other than cl-convert.

[dpsanders]

I was hoping that #16634 would fix this, but apparently not.

[andreasnoack]

I think there is still an issue here.

[StefanKarpinski]

How does this compare to 0.5? I.e. did this at least improve it somewhat?

[andreasnoack]

Seems to have improved a lot relative to 0.5 but my 0.5 results are quite a bit worse than the previous results reported in this issue. E.g. 500 tests take 385 seconds.

[StefanKarpinski]

Thanks, @andreasnoack. Good to know where we stand on all three versions. Seems like backporting the frontend speedup PR to 0.5 might be a good idea, and that some more improvement here would be even better.

[vtjnash]

In my measurements, https://github.com/JuliaLang/julia/tree/jn/frontend-cl-closure-perf is another ~10x faster. Does that close the performance gap for you on this test case?

[andreasnoack]

Unfortunately, I don't see a difference relative to master.

[vtjnash]

Maybe I'm looking at the wrong testcase. What one are you using?

[andreasnoack]

The one from the top post of this issue https://gist.github.com/anonymous/52b6599f6549c390b0e9.

[vtjnash]

I am seeing a net 2x speedup:

~/julia/zipyard$ time ../julia tests.jl
Facts
500 facts verified.

real	0m43.855s
user	0m42.506s
sys	0m0.668s

~/julia/zipyard$ time ../julia tests.jl
Facts
500 facts verified.

real	0m22.240s
user	0m21.681s
sys	0m0.455s

[andreasnoack]

I ran @IainNZ's updated version (in the same gist) except that I use Base.Test on 0.5 and 0.6. Have you tried that version?

[vtjnash]

Ah, OK. That one doesn't have any problem with lowering performance, but does have an issue with inference performance of code with branches. In that case, #19513 should give is a pretty good speedup.

[dpsanders]

On latest master, the time for N tests is still rather nonlinear in N.
It grows faster than a power law; if you fit a power law it's something like N^1.6.

Gist with new version that writes out test times to a data file:
https://gist.github.com/dpsanders/200c10be8ede3259d37cd5000d15d014

[KristofferC]

Tried this now and running up to 1000 tests and things still look very linear (and much much faster than the original examples)