2
\$\begingroup\$

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.

\$\endgroup\$
  • 7
    \$\begingroup\$ According to the docs, "Querying the GL_QUERY_RESULT implicitly flushes the GL pipeline..." Perhaps adding that flush is causing the timing to change? You could probably test that by removing the query and replacing it with a flush to see if you keep the speed increase. \$\endgroup\$ – user1118321 Jun 10 at 5:16
  • \$\begingroup\$ @user1118321 I've tried your suggestion and made an edit to the question containing the results. \$\endgroup\$ – Ryan1729 Jun 11 at 1:05
1
\$\begingroup\$

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.

\$\endgroup\$
  • \$\begingroup\$ For the purposes of my project, if the perceived latency is lowered and if complexity of the code that does that is contained within the rendering code, then that's better than the alternative. That said, if I disable the render timing with the conditional compilation described above, then on the current version of my code, any latency difference is not immediately noticeable. I haven't bothered to look back at the old version code or do proper timings yet, but I'll put that on my todo list. \$\endgroup\$ – Ryan1729 Jul 14 at 6:56
  • \$\begingroup\$ There have been several changes to the code since I originally posted this question, including an update to the library that handles interactions with the OS's event loop which included removal of an API I was using due to stability/complexity concerns. So that seems like the most likely cause for a real behaviour difference to me, at this time. If you are interested, the function in question was poll_events and you can read about the removal here. \$\endgroup\$ – Ryan1729 Jul 14 at 6:57

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.