Why is my openGL rendering faster when I time it with GL_TIME_ELAPSED

Question

I have some code that was rendering too slowly, as in there was a noticeable lag in when updating the screen in response to user input. I tried profiling the CPU side code, but that did not seem to be the problem. So I tried measuring the time taken on the GPU side. When I did that, the rendering suddenly got faster!

I've set up conditional compilation set up so I can switch back and forth and the slowness returns if I remove the GPU timing call. It seems like my graphics card manufacturer was trying to cheat on benchmarks or something? Is there any other reason why this would happen? Here's the code in question:

(I'm using Rust but I hope that the OpenGL calls are clear enough to someone familiar with OpenGL from other languages.)

let query_ids = [0; 1];
if cfg!(feature = "time-render") {
    unsafe {
        gl::GenQueries(1, query_ids.as_ptr() as _);
        gl::BeginQuery(gl::TIME_ELAPSED, query_ids[0])
    }
}
// render some stuff...
if cfg!(feature = "time-render") {
    let mut time_elapsed = 0;
    unsafe {
        gl::EndQuery(gl::TIME_ELAPSED);
        gl::GetQueryObjectiv(query_ids[0], gl::QUERY_RESULT, &mut time_elapsed);
        gl::DeleteQueries(1, query_ids.as_ptr() as _);
    }
    dbg!(time_elapsed);
}

Did I mess up the calls to OpenGL somehow? The timings I'm getting out seem reasonable enough: they are all around the same value, fluctuating up and down by a few 10s of microseconds.

Edit: I tried @user1118321's suggestion of removing the query and adding a glFlush, but that did not have the same effect as the time elapsed query.

I've modified the code as follows:

    if cfg!(feature = "time-render") {
        let finish_now = std::time::Instant::now();
        let mut time_elapsed = 0;
        unsafe {
            gl::EndQuery(gl::TIME_ELAPSED);
            gl::GetQueryObjectiv(query_ids[0], gl::QUERY_RESULT, &mut time_elapsed);
            gl::DeleteQueries(1, query_ids.as_ptr() as _);
        }
        let finish_nanos = finish_now.elapsed().as_nanos();
        println!("query took {}ms", finish_nanos as f64 / 1_000_000.0);
        println!("rendering took {}ms", time_elapsed as f64 / 1_000_000.0);
    } else {
        let flush_now = std::time::Instant::now();
        unsafe {
            gl::Flush();
        }
        let flush_nanos = flush_now.elapsed().as_nanos();
        println!("gl::Flush took {}ms", flush_nanos as f64 / 1_000_000.0);
    }

If I compile the program without "time-render" enabled I get output like this when running it:

gl::Flush took 0.0011ms
gl::Flush took 0.0023ms
gl::Flush took 0.0004ms
gl::Flush took 0.0009ms
gl::Flush took 0.0013ms
gl::Flush took 0.0004ms
gl::Flush took 0.0008ms
gl::Flush took 0.001ms
gl::Flush took 0.0012ms
gl::Flush took 0.0024ms

If I compile it with "time-render" enabled I get output like this:

query took 0.5638ms
rendering took 0.206504ms
query took 0.569ms
rendering took 0.206255ms
query took 0.5856ms
rendering took 0.204844ms
query took 0.5473ms
rendering took 0.205176ms
query took 0.5342ms
rendering took 0.205259ms
query took 0.5867ms
rendering took 0.213891ms
query took 1.3657ms
rendering took 0.216547ms
query took 1.538ms
rendering took 0.208828ms
query took 0.6028ms
rendering took 0.20833ms
query took 0.5656ms
rendering took 0.207168ms

So when "time-render" is enabled the code takes longer to run, but the screen updates faster! Bizarre.

I've done a little reading on glFlushand this answer to a different question notes that calling glFlush before swapping the buffers in a double buffering setup will have no effect. So, it might be worth mentioning that the very net thing that happens after the function that contains the code I posted is run, is this swap_buffers function from a library is called. It then calls into platform specific code, but presumably it is using the OpenGL symbol I passed to it during startup to swap buffers for me.

Edit 2: I decided to try glFinish instead of glFlush in the above code, for completeness. If I do, then the percieved speed is actually as fast as with "time-render" enabled above! I get output like this though:

gl::Finish took 2.0424ms
gl::Finish took 1.6895ms
gl::Finish took 1.8569ms
gl::Finish took 2.7918ms
gl::Finish took 1.5629ms
gl::Finish took 1.4513ms
gl::Finish took 1.6008ms
gl::Finish took 1.7746ms
gl::Finish took 2.5587ms
gl::Finish took 1.7089ms

...which indicates that the code is taking slightly longer to complete than the GPU rendering and the time query combined. I also measured the total time the function containing the posted code took, and that bore that conclusion out. So I guess I'm going to keep the timing query in then, since in seems to be the fastest! I can only guess at what's happening inside the GPU/graphic driver but maybe the implicit flushing that the query does is skipping something that glFinish does? If that's the case, then it doesn't seem to be affecting the actual rendering! That at least sort of makes sense, I think.

Answer 1

This is a very poor design even before the issues you mentioned came to light.

In order to make these queries asynchronous like they are supposed to be, you're expected to jam a fence into the command queue immediately following the issue of the end timestamp.

Now, evidently the temptation in this code snippet is to read the value of end immediately, but ... surprise, surprise, the GPU has not even started working on your frame yet and waiting on the result is going to sit and spin while 2-4 or more frames go through the render pipeline and the GPU finally gives you a timestamp counter that you can readback.

If you do manage to read something back without waiting, the results are going to be undefined.

You are killing CPU/GPU parallelism and more than likely don't want performance measurements taken while the render pipeline is in duress.

This is why your code is full of horrible flush / finish commands. Stop doing that and use a fence sync object instead. Once per-frame check the status of the fence you planted after your timestamp query. If the fence is signaled, now you can readback the timer query with no ill-effects.

The GL, of course, has a way of checking whether queries are ready, but this is how that check is more or less implemented and other APIs basically require you to put fences in the command stream to figure out whether a command is retired yet or not, so it's handy to learn.

This most likely doesn't answer your question, however, if you're willingly waiting on something to finish that's generated through pipelined execution there's no telling what else is wrong with your software. I'd do a quick survey of all read-back sites and try to develop any code using those readbacks the ability to tolerate 3-4 frames of latency.