possible type instability in translate_cam

[SimonDanisch]

Found by @CrashBurnRepeat.
Will need some tests (maybe call the function directly) and should be easy to fix!

[CrashBurnRepeat]

Thanks for posting this! I've been doing some digging and I think I have a solution to this issue.

The modifications I've made so far have seemed to worked, and had a significant impact on the @time metrics, if those are to be trusted. The two main changes are to the translate_cam definition (as expected) and in where it's called in PerspectiveCamera

The change in translate_cam:

function translate_cam(
        translate::T,
        proj::Mat4{Float32},
        view::Mat4{Float32},
        window_size::SimpleRectangle{Int},
        prj_type::Projection,
        eyepos_s::T,
        lookat_s::T,
        up_s::T,
    ) where T<:Vec3

The change in PerspectiveCamera:

preserve(map(translate_cam,
       trans, projectionmatrix, viewmatrix, window_size,
       projectiontype,  eyeposition, lookatposition, upvector
    ))

This second change may be less apparent, but previously the call used Signal to make every argument except trans a Signal, even though, from what I can tell, these are all Signal type already.

If it's of interest, the @time metrics for the current master running rotate_robj.jl are:

56.212418 seconds (23.23 M allocations: 1.153 GiB, 1.15% gc time)

with the new metrics being:

48.460147 seconds (15.92 M allocations: 805.743 MiB, 0.68% gc time)

If you'd like, I can create a pull request for what I have already, but I haven't created any new tests. Any suggestions on what would be a good one, or ones?

[SimonDanisch]

Could it be, that you are measuring compilation times? These could actually be influenced by typing the arguments... I can play around with that a bit.
The function itself seems type stable!

[SimonDanisch]

Ah, btw you're change is wrong. These need to be Signal(Signal(x)), so that I can actually push to the signal from within translate_cam!

[CrashBurnRepeat]

These need to be Signal(Signal(x)), so that I can actually push to the signal from within translate_cam!

Ok, I'll revert that change and test to make sure things still work as expected. You also mentioned creating some tests?

I'll also do some more experimentation on the performance side. At the very least I'll get some data to show why I wrote you about this particular function.

[CrashBurnRepeat]

I went back and reproduced the work that led me to ask about translate_cam in the first place. The commands I used to produce the profiling information:

julia> using GLVisualize

julia> Profile.init(n=10^7)

julia> @profile include("/Users/crashburnrepeat/.julia/v0.6/GLVisualize/examples/introduction/rotate_robj.jl")

julia> using ProfileView

julia> ProfileView.view()

Admittedly, this @profile command will include compiling information, since it's the first execution of rotate_robj.jl. However, it produces the following profile graph:

The axes here are roughly time on the horizontal and dependent function calls on the vertical. The text on the lower part of the graph shows that something on line 482 of GLCamera.jl is causing a lot of long-running calls to inference.jl (not shown on the graph, but everything above the text is an inference.jl call). This line corresponds to:

preserve(map(translate_cam,
       trans, Signal(projectionmatrix), Signal(viewmatrix), Signal(window_size),
       Signal(projectiontype),  Signal(eyeposition), Signal(lookatposition),
       Signal(upvector)
    ))

Which led me to translate_cam, as it did not strictly type its input arguments.

Since I mentioned timing information, starting a new Julia session:

julia> using GLVisualize

julia> @time include("/Users/crashburnrepeat/.julia/v0.6/GLVisualize/examples/introduction/rotate_robj.jl")
 26.447453 seconds (16.62 M allocations: 827.748 MiB, 1.14% gc time)

julia> @time include("/Users/crashburnrepeat/.julia/v0.6/GLVisualize/examples/introduction/rotate_robj.jl")
  2.958808 seconds (608.49 k allocations: 27.085 MiB, 0.29% gc time)

This does contradict my earlier @time data, so I'm not sure how I got those numbers. Perhaps I forgot the using GLVisualize command? In any event, this is now my master starting point.

For the strictly typed translate_cam (before running these tests, I went back and corrected the Signal(Signal(a)) error I made, so I believe this is functioning as intended), running the same profiling experiment yields:

Where GLCamera.jl corresponds to the green bar in the center of the text. Visually at least, it appears that we've cut out an enormous amount of calls to inference.jl and the corresponding time cost. There are still a good number of calls coming from other system functions, but that's of course way beyond the scope of this issue.

Similarly, running the same @time experiment:

julia> using GLVisualize

julia> @time include("/Users/crashburnrepeat/.julia/v0.6/GLVisualize/examples/introduction/rotate_robj.jl")
 26.008013 seconds (15.83 M allocations: 800.969 MiB, 1.06% gc time)

julia> @time include("/Users/crashburnrepeat/.julia/v0.6/GLVisualize/examples/introduction/rotate_robj.jl")
  3.037481 seconds (607.70 k allocations: 27.037 MiB, 0.30% gc time)

There does seem to be a noticeable, if small, improvement to the compilation metrics, but the post-compilation metrics are virtually identical. I'm a bit confused as to why the improvement to the compilation times weren't greater based on the original ProfileView graph, but a question for another package I suppose.

In any event, thanks for holding me to some rigor and I hope that explains more of where I was coming from in my original line of questioning. Even if it's not the speed improvement I hoped, at least the added typing should help going forward.

[CrashBurnRepeat]

I've added a test for translate_cam but I'm not certain it's testing the right thing. As always, if I've misunderstood your intent, let me know. Thanks!