Regression in methodshow/print_to_string

[dhoegh]

I have observed a regression of a factor of 2-3 between master and 0.3.8 in the following test case:

function test1(n)
    for i=1:n
        string(methods(max))
    end
end
test1(1)
@time test1(10000)

0.3.8 runs in 2.467998002 s while master takes 7.016 s.

[IainNZ]

Isn't this function only used interactively? And isn't the difference less than a human can perceive?

[dhoegh]

Yes, but I do not think the root cause is inside the methodshow but in the string conversion. I have not been able to track the exact difference down.

[dhoegh]

The regression occurred between 8fc5b4e and c6d0759 where no change have been made in methodshow.jl, but #10380 where merged in this interval.

I hope someone is able to track down the exact regression.

[KristofferC]

Maybe you can test the commit before and see if it is fast again then? Or alternative just do a full fledged bisection.

[dhoegh]

I can confirm that the time goes from 2.3s to 3.7s at 9da1662 while the time is 6.3 at b37323c.

[dhoegh]

I have tried to track this further. The following goes from 14.7s to 20.6s post #10380

function test(n)
           a=rand(300)
           for i=1:n
               Base.print_to_string(a...)
       end
end
test(100)
@time test(100000)

[JeffBezanson]

My best guess is that this is caused by the call to jl_f_tuple used to allocate varargs tuples (

julia/src/codegen.cpp

Line 4613 in 99391b3

builder.CreateCall3(prepare_call(jltuple_func), V_null,

). It now has extra overhead for constructing the type of the tuple, and then the tuple itself. This can be fixed by constructing the type at compile time, since we usually know it.

Another possibility is that the optimization to elide varargs tuples has regressed in some cases.

[JeffBezanson]

Now an additional ~5x slower, with all the time in is_exported_from_stdlib.

[mbauman]

I'm on a phone so I can't measure it, but Jeff already fixed at least some of it: c2d35bb (thanks Jeff!)

[KristofferC]

0.3.12 runs #11700 (comment) at 10 seconds, master at 11.5 seconds. Seems close enough to close.