Fix incorrect timing results for CUDA.@elapsed

[thomasfaingnaert]

No description provided.

[vchuravy]

Could you also add a test?

[thomasfaingnaert]

Added a test that checks that a naive matmul's runtime scales (approximately) cubicly. This might be a bit flaky, though, so I'm open to suggestions on other ways to test this.

[vchuravy]

I was more thinking that you changed the macro to interpolate code and not ex. So what did this fix? Reading the code it seems the only difference is the splitting off of keyword arguments?

[thomasfaingnaert]

Here's an example illustrating the issue:

using CUDA

function simple_matmul(C, A, B, N)
    for i = 1:N
        for j = 1:N
            @inbounds elem = C[i, j]

            for k = 1:N
                @inbounds elem += A[i, k] * B[k, j]
            end

            @inbounds C[i, j] = elem
        end
    end

    nothing
end

A = CuArray(rand(Float32, (1000, 1000)))
B = CuArray(rand(Float32, (1000, 1000)))
C = similar(A)

# warmup
@cuda simple_matmul(C, A, B, 500)

N1 = CUDA.@elapsed @cuda simple_matmul(C, A, B, 500)
N2 = CUDA.@elapsed @cuda simple_matmul(C, A, B, 1000)

println(N1)
println(N2)

With this PR, this outputs:

4.490149
51.85088

Without this PR, I get:

1.888e-6
3.84e-6

For other kernels I've seen similar results: CUDA.@elapsed returning something in the order of a couple microseconds, no matter the complexity of the kernel.

Reading the code it seems the only difference is the splitting off of keyword arguments?

Yes, and I'm not exactly sure why the code as written in #2113 leads to this behaviour, because, as you said, the only difference should be the keyword arguments, which shouldn't impact the results.

[vchuravy]

What is the @macroexpand1 before and after?

[thomasfaingnaert]

julia> @macroexpand1 CUDA.@elapsed @cuda simple_matmul(C, A, B, 500)
quote
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:119 =#
    (var"#23#t0", var"#24#t1") = (CUDA.CuEvent(), CUDA.CuEvent())
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:120 =#
    CUDA.record(var"#23#t0")
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:121 =#
    (:(#= REPL[17]:1 =# @cuda simple_matmul(C, A, B, 500)),)
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:122 =#
    CUDA.record(var"#24#t1")
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:123 =#
    CUDA.synchronize(var"#24#t1"; blocking = false)
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:124 =#
    CUDA.elapsed(var"#23#t0", var"#24#t1")
end

julia> @macroexpand1 CUDA.@elapsed_fixed @cuda simple_matmul(C, A, B, 500)
quote
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:148 =#
    (var"#25#t0", var"#26#t1") = (CUDA.CuEvent(), CUDA.CuEvent())
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:149 =#
    CUDA.record(var"#25#t0")
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:150 =#
    #= REPL[18]:1 =# @cuda simple_matmul(C, A, B, 500)
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:151 =#
    CUDA.record(var"#26#t1")
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:152 =#
    CUDA.synchronize(var"#26#t1"; blocking = false)
    #= /home/tfaingna/.julia/dev/CUDA/lib/cudadrv/events.jl:153 =#
    CUDA.elapsed(var"#25#t0", var"#26#t1")
end

[vchuravy]

So... They are identical?

[thomasfaingnaert]

No, there's a small difference:

(:(#= REPL[17]:1 =# @cuda simple_matmul(C, A, B, 500)),)

vs.

#= REPL[18]:1 =# @cuda simple_matmul(C, A, B, 500)

(Admittedly, it also took me some time to notice...)

[thomasfaingnaert]

Anyway, the problem thus is that the code is inserted as a 1-element tuple containing the to-be-benchmarked Expr, rather than just that Expr itself.

I adapted the test to check this.