Hi,
I'm having an issue getting plausible values at certain times with a disjoint timer query. I've read the discussion in here but my issue seems slightly different.
I'm not trying to time individual draw calls but rather the time it takes for complete the backbuffer.
I'm getting "roughly" consistent numbers for a large part of the frames, but frequently get 18446744073709551615 (2^64-1). This happens even when glGetQueryObjectuiv() returns true for an available query. Here's a snippet of the code (which is a slightly modified version this Unity plugin to use a 64-bit query):
GLuint available = 0; glGetQueryObjectuiv(queryObject, GL_QUERY_RESULT_AVAILABLE, &available); if (available == GL_TRUE) { GLuint64 elapsed_time_ns; glGetQueryObjectui64vEXT(queryObject, GL_QUERY_RESULT, &elapsed_time_ns); if (glGetError() == GL_NO_ERROR) { ... } ... }
I've tried forcing a synchronous call by ignoring the availability of the result. In such cases, the MAX_UINT above doesn't seem to occur and the values are "roughly" consistent (sometimes a few ms apart, but that's perhaps due HW pipelining).
I've gone through the extension spec but I can't find anything that might explain this. Could I've missed something?
I'm running this on a Samsung A20 with a Mali-G71. I've tried the same test on a device with an old Adreno 330 and I don't seem to get the same issue though.
Hi José! Thanks for the reply. Here's the version I have: OpenGL ES 3.2 v1.r16p0-01rel0
Hi, our r16p0 driver had a bug that the queried elapse time is a very large number (not the nano second), however, it should not be 2^64-1. Is your test like this?glGenQueriesEXT(1, &queryObject);
glBeginQueryEXT(GL_TIME_ELAPSED_EXT, queryObject)
draw
swap or finish or nothing
glEndQueryEXT(GL_TIME_ELAPSED_EXT)
and then the query code you pasted above
Hi Sunny, thanks for the reply. Here's some abbreviated pseudo-code of what I'm doing (this is largely based on an open source Unity plugin :
void BeforeRenderingStarts() { // on disjoint exception, clear query buffer GLint disjointOccurred = false; glGetIntegerv(GL_GPU_DISJOINT, &disjointOccurred); if (disjointOccurred) { query_buffer_n = 0; __android_log_print(ANDROID_LOG_ERROR, "Timer", "Disjoint Exception occurred"); } // read result of oldest pending query // We use buffering to avoid blocking when reading results. elapsed_time_seconds = NAN; // NOTE_JPJ: if ran synchronously below NAN is caught by the thread reading this value - consider using the last frame's one if (query_buffer_n > 0) { int index = (query_buffer_next_index + (BUFFER_SIZE - query_buffer_n)) % BUFFER_SIZE; GLuint available = 0; glGetQueryObjectuiv(queries[index], GL_QUERY_RESULT_AVAILABLE, &available); if (available == GL_TRUE) { GLuint64 elapsed_time_ns; glGetQueryObjectui64vEXT(queries[index], GL_QUERY_RESULT, &elapsed_time_ns); if (glGetError() == GL_NO_ERROR) { __android_log_print(ANDROID_LOG_VERBOSE, "Timer", "The value of the timestamp is elapsed %llu. ", elapsed_time_ns); } else { // log error } --query_buffer_n; } } // start new query if (query_buffer_n < BUFFER_SIZE) { glBeginQuery(GL_TIME_ELAPSED, queries[query_buffer_next_index]); if (glGetError() == GL_NO_ERROR) { query_buffer_next_index = (query_buffer_next_index + 1) % BUFFER_SIZE; ++query_buffer_n; } else { // log error } } else { // log overflow } } void AfterRenderingEnds() { glEndQuery(GL_TIME_ELAPSED); if (glGetError() != GL_NO_ERROR) { // log error } }
Is there anything in particular that catches your eye?
I'll have a look at exactly where the START/END functions above are placed in the GL pipeline since this is triggered from Unity callbacks.
From the Unity plug in, I don't know how "query_buffer_n" and "query_buffer_next_index " are set. So I don't know if it tracks the same query object (using same index/query_buffer_next_index for begin and end), can you check this? and also please check if glGetError() reports errors
Hi Sunny,
That's a fair point. If I'm getting it right you're saying that you can't be certain that I'm querying the value of an object that has been terminated? That could be a cause but I don't know why the availability would return true. I'll do some more investigation. Cheers
For the r16p0 driver, it should return a reasonable data from glGetQueryObjectui64vEXT(GL_QUERY_RESULT), the only problem for that version driver is that the returned data is not in the unit of nanosecond, you should apply this equation:
ns = result * 1000 / AGT_FREQUENCY_MHZ
AGT_FREQUENCY_MHZ is the Arm Generic Timer that used in A20, if you don't know we can check with Samsung
I was about to reply to you. I've done some more investigation on this. I can't find any issue with the code related with the snippet above. I've tried having a single query object as well as quite a few more - the behavior is the same.Having said this, I've run the same app on an S10e (G970F) and I also get the same large number returned, albeit, less often. Furthermore, I've also ran the app through RenderDoc to get some GL stack data. In a nutshell, here's "where" the query is placed in terms of the GL pipeline:
// App init - presumbaly Backbuffer is bound upon the initialization of eGL glBindFramebuffer(auxFBO, DRAW) glInvalidateFramebuffer(...) // makes no sense to me but... // expected glGetQueryObjectui64vEXT() here glBeginQuery() ... ... some more calls glBindFramebuffer() for shadowmap and back to auxFBO ... glEndQuery() ... quite a few more GL calls (state, FBO binds, etc..) including draw calls eglSwapBuffers()
So, not quite covering the whole scope of the frame. I believe glGetQueryObjectui64vEXT() is not showing up in the stack since this was done through a RenderDoc capture and it perhaps hadn't finished yet (?).
Not sure how this can influence the timer - perhaps you can shed some light on that. Thanks for your help.
Our driver will also have a wait in glGetQueryObjectui64vEXT(GL_QUERY_RESULT_EXT) if GL_QUERY_RESULT_AVAILABLE_EXT is not called, and the result is initialized to 0.
Can you please try this?
GLuint query; GLuint64 time; GLuint dis_result = 0; glGenQueriesEXT(1, &query); glBeginQueryEXT(GL_TIME_ELAPSED_EXT, query); glClear(GL_COLOR_BUFFER_BIT); glEndQueryEXT(GL_TIME_ELAPSED_EXT); while (!dis_result) { glGetQueryObjectuivEXT(query, GL_QUERY_RESULT_AVAILABLE_EXT, &dis_result); } glGetQueryObjectui64vEXT(query, GL_QUERY_RESULT_EXT, &time); __android_log_print(ANDROID_LOG_ERROR, "Timer", "elapsed time is: %lld\n", (long long)time); glDeleteQueriesEXT(1, &query);
I can always get something like
elapsed time is: 4273
So if you are still getting -1, I think I have to contact Samsung if they changed the driver a little bit.
Thanks for the quick reply. I've inserted that code snippet at the beginning of the frame (after checking the disjoint query) in the same codebase I was using, like so (for clarity):
void BeforeRenderingStarts() { // on disjoint exception, clear query buffer GLint disjointOccurred = false; glGetIntegerv(GL_GPU_DISJOINT, &disjointOccurred); if (disjointOccurred) { query_buffer_n = 0; __android_log_print(ANDROID_LOG_ERROR, "Timer", "Disjoint Exception occurred"); } { GLuint query; GLuint64 time; GLuint dis_result = 0; glGenQueries(1, &query); glBeginQuery(GL_TIME_ELAPSED, query); glClear(GL_COLOR_BUFFER_BIT); glEndQuery(GL_TIME_ELAPSED); while (!dis_result) { glGetQueryObjectuiv(query, GL_QUERY_RESULT_AVAILABLE, &dis_result); } glGetQueryObjectui64vEXT(query, GL_QUERY_RESULT, &time); __android_log_print(ANDROID_LOG_ERROR, "Timer", "elapsed time is: %lld\n", (long long)time); glDeleteQueries(1, &query); } ...
I don't seem to get any issues with that though. I get different values I'd consider plausible (e.g., 461268, 741576, etc...).
Regarding the pseudo GL stack I mention above, I forgot to mention that I don't seem to be able to trigger that anomaly (the -1 value) if I remove the shadow pass. Essentially this:
// App init - presumbaly Backbuffer is bound upon the initialization of eGL glBindFramebuffer(auxFBO, DRAW) glInvalidateFramebuffer(...) // makes no sense to me but... // expected glGetQueryObjectui64vEXT() here glBeginQuery() ... ... NO SHADOW PASS IN HERE.. ... glEndQuery() ... quite a few more GL calls (state, FBO binds, etc..) including draw calls eglSwapBuffers()
I can provide an MGD dump if that helps (and you have time to look into this of course). It's nothing but a simple (but rather shadowmap-heavy) scene rendering a bunch of spheres. Thanks for your help so far!
461268 and 741576 looks reasonable (just because your platform has different frequency setting)
yes, please provide an MGD or sample code for the shadow pass
Cheers Sunny! Will send it over soon.
Please find below the MDG trace from the app. Please let me know if that's sufficient or of any other issue you might have. Thanks once more for your help.
render-timing-original.zip
Hi Sunny, did you manage to have a look at the MGD trace? Cheers, Joao
I will have a look
I have created an internal ticket to handle this. I had a brief check with the MGD file, it seems to me that it queries the elapsed time stamp for every renderpass. That should be OK to me.
so I am setting up the Arm DS environment to run the trace, I hope it can give me some ideas
Cheers!