radeonsi: Android fences return the timestamp of the completion of the last command, not the beginning of the next command
Mesa version: 19.2.3 Kernel version: 5.3.8
I am trying to use EGLSync objects to time how long a rendering batch takes, by inserting one before and after my GL commands, and extracting the sync file and timestamp from it.
EGLSyncKHR start, end;
int start_fence, end_fence;
start = eglCreateSyncKHR(egl, EGL_SYNC_NATIVE_FENCE_ANDROID, NULL);
glClear(GL_COLOR_BUFFER_BIT);
end = eglCreateSyncKHR(egl, EGL_SYNC_NATIVE_FENCE_ANDROID, NULL);
eglSwapBuffers(egl, surface);
start_fence = eglDupNativeFDANDROID(egl, start);
end_fence = eglDupNativeFDANDROID(egl, end);
Full code tested with found here: https://github.com/ascent12/compositor-killer/tree/5fb523b98ec5eff376909876ed7ccbf1e8bb0088
Example output from my program:
Took 16.058917 ms to render (48296951602834 - 48296967661751)
Took 16.837974 ms to render (48296967661751 - 48296984499725)
Took 16.708162 ms to render (48296984499725 - 48297001207887)
Took 16.032808 ms to render (48297001207887 - 48297017240695)
Took 17.369029 ms to render (48297017240695 - 48297034609724)
Took 16.016286 ms to render (48297034609724 - 48297050626010)
Took 17.353199 ms to render (48297050626010 - 48297067979209)
Took 15.979649 ms to render (48297067979209 - 48297083958858)
Took 17.412811 ms to render (48297083958858 - 48297101371669)
Took 16.055880 ms to render (48297101371669 - 48297117427549)
Took 17.296393 ms to render (48297117427549 - 48297134723942)
Obviously it's not taking 16-17 ms to execute glClear(). The time appears to be my monitor's refresh rate. When the same code is run on i915, I get the expected result of a few hundred microseconds.
Changing the creation of the start fence to
start = eglCreateSyncKHR(egl, EGL_SYNC_NATIVE_FENCE_ANDROID, NULL);
glFlush();
start_fence = eglDupNativeFDANDROID(egl, start);
glClear(GL_COLOR_BUFFER_BIT);
// ...
makes no difference.
As discussed on IRC, this may be happening because radeonsi is not treating the creation of an EGLSync as a command on the OpenGL command stream, and could possibly be reusing a previous fence.
From https://www.khronos.org/registry/EGL/extensions/ANDROID/EGL_ANDROID_native_fence_sync.txt
When a fence sync object is created or when an EGL native fence sync object is created with the EGL_SYNC_NATIVE_FENCE_FD_ANDROID attribute set to EGL_NO_NATIVE_FENCE_FD_ANDROID, eglCreateSyncKHR also inserts a fence command into the command stream of the bound client API's current context (i.e., the context returned by eglGetCurrentContext), and associates it with the newly created sync object.
I believe the current behaviour is not conformant to this specification.
Ideally, this would generate a proper fence command, and provide a useful timestamp as the "starting point" of a rendering batch, where it can be compared to a fence inserted at the end. Besides my small example program, I know that Weston was also trying to make use of this for its own rendering measurements.