Inconsistent timing between OpenGL and Metal

[whabilly]

I have this simple loop to measure the bgfx timing under various conditions:

	// gbfx Timing Stats (frame duration = mean ± std)
	int nbframes = 60;
    	double meanCpuTimeFrame = 0.;
    	double stdCpuTimeFrame = 0.;
    	for (int i=0; i<nbframes; i++) 
    	{			
        	bgfx::touch(0);
        	bgfx::frame();
 
 	       	const bgfx::Stats stats = *bgfx::getStats();
 	       	double cpuTimeFrame = (double)stats.cpuTimeFrame;
 	       	meanCpuTimeFrame += cpuTimeFrame; 
 	       	stdCpuTimeFrame += cpuTimeFrame*cpuTimeFrame;

		// printf(“cpuTimeFrame: %f\n”, cpuTimeFrame);
 	}
	meanCpuTimeFrame = meanCpuTimeFrame/nbframes; 
 	stdCpuTimeFrame = sqrt(stdCpuTimeFrame/nbframes-meanCpuTimeFrame*meanCpuTimeFrame);
 	printf("bgfx::cpuTimeFrame = %f ± %f ms\n", meanCpuTimeFrame/1000., stdCpuTimeFrame/1000.);

In the single threaded mode (by calling bgfx::renderFrame() before bgfx::init) with the flags BGFX_RESET_VSYNC | BGFX_RESET_FLIP_AFTER_RENDER | BGFX_RESET_FLUSH_AFTER_RENDER, I typically obtain the following results:

bgfx::cpuTimeFrame = 16.663783 ± 0.260285 ms for OpenGL

This is consistent with my display’s frame rate of 60 Hz. Variability is typically ok (< 0.5 ms) though this seems to be a bit high since the above loop does nothing more than clearing view 0.

However with Metal as the renderer, I get a completely different result:

bgfx::cpuTimeFrame = 8.331800 ± 8.071231 ms

This is obviously not what I expected. Printing out the cpuTimeFrame in the above loop shows that it consistently alternates between 0.5 and 16 ms for Metal which is not the desired behavior. Each frame duration should be approximately 16 ms and I would expect the timing variability to be similar or less than for OpenGL.

BGFX_RESET_FLIP_AFTER_RENDER and BGFX_RESET_FLUSH_AFTER_RENDER have not effect on the Metal timing. Moreover bgfx::shutdown() fails to return when using BGFX_RESET_FLIP_AFTER_RENDER, and seems stuck in an infinite loop.

I’m using glfw by the way under macOS 10.12.6. A side question about the single threaded mode: what is the difference between using --with-glfw to build bgfx (ie with BGFX_CONFIG_MULTITHREADED=0) and calling bgfx::renderFrame before bgfx:init? Should I expect different behaviors??? Thanks!

[mcourteaux]

I'm facing this issue today as well. Shutdown freezes when using BGFX_RESET_FLIP_AFTER_RENDER. This is the stack trace upon the freeze in shutdown():

(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00007fff688d3e36 libsystem_kernel.dylib`semaphore_wait_trap + 10
    frame #1: 0x00007fff68739aed libdispatch.dylib`_dispatch_sema4_wait + 16
    frame #2: 0x00007fff68739fbf libdispatch.dylib`_dispatch_semaphore_wait_slow + 98
    frame #3: 0x000000010d27ec0d silvernode`bx::Semaphore::wait(this=0x00000001138ac320, _msecs=<unavailable>) at semaphore.cpp:106:11 [opt]
    frame #4: 0x000000010d229e0e silvernode`bgfx::mtl::RendererContextMtl::shutdown() [inlined] bgfx::mtl::CommandQueueMtl::consume(this=0x00000001138ac320) at renderer_mtl.mm:3452:21 [opt]
    frame #5: 0x000000010d229e04 silvernode`bgfx::mtl::RendererContextMtl::shutdown() at renderer_mtl.mm:3434 [opt]
    frame #6: 0x000000010d229dbc silvernode`bgfx::mtl::RendererContextMtl::shutdown() [inlined] bgfx::mtl::CommandQueueMtl::shutdown(this=0x00000001138ac320) at renderer_mtl.mm:3381 [opt]
    frame #7: 0x000000010d229dbc silvernode`bgfx::mtl::RendererContextMtl::shutdown(this=<unavailable>) at renderer_mtl.mm:717 [opt]
    frame #8: 0x000000010d229180 silvernode`bgfx::mtl::rendererDestroy() at renderer_mtl.mm:2403:16 [opt]
    frame #9: 0x000000010d1fb109 silvernode`bgfx::Context::rendererExecCommands(bgfx::CommandBuffer&) [inlined] bgfx::rendererDestroy(_renderCtx=<unavailable>) at bgfx.cpp:2651:4 [opt]
    frame #10: 0x000000010d1fb0ed silvernode`bgfx::Context::rendererExecCommands(this=0x0000000116f23040, _cmdbuf=0x000000011a0f7aa8) at bgfx.cpp:2721 [opt]
    frame #11: 0x000000010d1f5da7 silvernode`bgfx::Context::renderFrame(this=0x0000000116f23040, _msecs=-1) at bgfx.cpp:2346:5 [opt]
    frame #12: 0x000000010d1f9b2f silvernode`bgfx::Context::swap(this=0x0000000116f23040) at bgfx.cpp:2250:4 [opt]
    frame #13: 0x000000010d1f7495 silvernode`bgfx::Context::frame(bool) [inlined] bgfx::Context::frameNoRenderWait(this=0x0000000116f23040) at bgfx.cpp:2215:3 [opt]
    frame #14: 0x000000010d1f748d silvernode`bgfx::Context::frame(this=0x0000000116f23040, _capture=<unavailable>) at bgfx.cpp:2206 [opt]
    frame #15: 0x000000010d1f7ad2 silvernode`bgfx::Context::shutdown(this=0x0000000116f23040) at bgfx.cpp:1960:3 [opt]
    frame #16: 0x000000010d1fbda3 silvernode`bgfx::shutdown() at bgfx.cpp:3493:8 [opt]