@test is extremely slow in 0.5 for BusinessDays.jl

[felipenoris]

I put up a gist at https://gist.github.com/felipenoris/3dbd7ff6a830be372e45dc337bb204cf with the slow code.

Once julia reaches line 19:

for usecache in [ false, true ]

it takes a long time to start executing what´s inside the for loop.

If I just unroll the loop (see https://gist.github.com/felipenoris/d9ba8d9ee5b116d259a6de3189418055), it runs smoothly, just like 0.4 does.

JuliaFinance/BusinessDays.jl#4
#18276

[aviks]

This seems to be purely due to the overhead of compiling the large block. Even when moving the block of code inside the loop into a function, the first execution of the function takes a long time.

FWIW, a Profile output is https://gist.github.com/aviks/252a7373738e97b5ee66587716d64d94

[aviks]

I have done a simpler testcase, that does not use any additional packages: https://gist.github.com/aviks/d5152303cbf23eef6f69bc8a5919151d

This is a function with around 500 lines in it. Each line is a @test macro. On 0.4

julia> include("/Users/aviks/test_18361.jl")
Started loading. All times relative to now
Finished loading function 0 milliseconds
Compiled, started execution 1000 milliseconds
Finished Execution 3000 milliseconds

On 0.5, its about 500 times worse.

julia> include("/Users/aviks/test_18361.jl")
Started loading. All times relative to now
Finished loading function 1987 milliseconds
Compiled, started execution 487572 milliseconds
Finished Execution 487591 milliseconds

I tried this with a 1000 line function, and went for a walk. My laptop went to sleep before the code completed.

[tkelman]

what about with BaseTestNext on 0.4, or with Julia 0.5 but using LLVM 3.3? how much of this is compiler regression and how much is changed implementation of @test ?

[yuyichao]

In a similar case I've seen ~60% time in the parser/lowering 40% in type inference.

[vtjnash]

that's a duplicate of #15346. although, you also might want to caffeinate your computer :)

[aviks]

I believe this is due to compile time. If I remove the function definition, and put 500 @test macros at the top level in the file, execution time is at a very acceptable 500 milliseconds. Once it tries to compile those lines as block, either within a function or an for expression, the compile time goes crazy.

Going back to the original function definition, there is clearly some exponential growth in compile time, as function of the number of lines of code inside the function

Given this, is this the same as #15346 ?

[timholy]

There's even the insane example in #16122, which is still with us (and perhaps even worse than before).

[felipenoris]

On @tkelman's compiler regression vs @test implementation.

If I use test.jl from 0.4, and put it to run on 0.5:

julia> VERSION
v"0.5.0-rc0+61"

julia> include("test.jl") # taken from 0.4 release
Test

julia> include("test_18361.jl")    # code change: using Test
Started loading. All times relative to now
Finished loading function 7517 milliseconds
Compiled, started execution 14850 milliseconds
Finished Execution 14855 milliseconds

This result is way faster than Avik's, and shows that @test got slow on 0.5.

On 0.4, it's even faster: (same result from Avik's test)

julia> VERSION
v"0.4.7-pre+3"

julia> include("test_18361.jl")
Started loading. All times relative to now
Finished loading function 0 milliseconds
Compiled, started execution 1000 milliseconds
Finished Execution 3000 milliseconds

[JeffBezanson]

The problem with many tests is most likely #18077, which is caused by our inlining a large number of try-catch blocks, and the performance of inference in that case.

[felipenoris]

The big hit in this case seems to be @test implementation itself.
If I borrow test.jl from 0.5 and apply it to 0.4, I get a very bad result.

julia> include("test_0.5.jl") # borrowed from 0.5
Test

julia> include("test_18361.jl") # using Test
Started loading. All times relative to now
Finished loading function 10000 milliseconds
Compiled, started execution 433000 milliseconds
Finished Execution 433000 milliseconds

julia> VERSION
v"0.4.7-pre+3"

[JeffBezanson]

Yes, the implementation of @test is part of it, but is not itself what takes the time --- the time is taken by the compiler on this code pattern.

[felipenoris]

Ok. Let me put it this way: given the change in @test code, it exposes a compiler performance issue that was there in 0.4 version as well.

[ViralBShah]

Closing as a dup of #18077. I suspect this issue will surface in other packages too.