Severe slowdown during certain 2D scenes on Raspberry Pi 4 (GLES 3.1)

dankcushions commented 4 years ago

The Raspberry Pi 4 does an OK job in most 3D games, but for some reason certain 2D scenes really slow things down, which makes me think there's some optimization issue - perhaps a shader that needs streamlining?

For example - Goldeneye 007 is full speed during the intro until the moment the gun barrel moves during this part: SentimentalBreakableBurro-small As soon as the barrel moves, everything is slow. It then speeds up once it stops and Bond fires, and then is very slow again once you enter the 2D menu: goldeneye-007 (it's slower in other parts of the menu, but slowest here)

Is there a particular option(s) I could turn off to isolate the problem? Or a log that would be useful? only lines in gliden64.log are:

2020/09/16,15:36:14.184,opengl_Utils.cpp:60,WARNING, "Could not query EGL extensions on this device"
2020/09/16,15:36:14.188,opengl_Utils.cpp:60,WARNING, "Could not query EGL extensions on this device"

I believe this was also an issue with Raspberry Pi 3, so I'm curious if it's a common issue with all low-powered GLES devices (@fzurita, any ideas if this happens on Android devices?).

I believe @loganmc10 looked into this a while back and theorised it was to do with LOD or texturing. Any pointers?

fzurita commented 4 years ago

I don't see this in Android devices. Does OpenGL threading help with this?

You could turn on OpenGL debug and profiling mode to figure out what is holding up the driver in the Raspberry Pi 4.

loganmc10 commented 4 years ago

I believe a lot of 2D games really slam the texture cache. The RPi3 had issue with it, and even had its own default texture cache size:

https://github.com/gonetz/GLideN64/blob/master/src/Textures.h#L104-L108

You might try playing with the m_maxCacheSize value to see if anything there improves things.

dankcushions commented 4 years ago

@fzurita

I don't see this in Android devices. Does OpenGL threading help with this?

threading is on in my case

You could turn on OpenGL debug and profiling mode to figure out what is holding up the driver in the Raspberry Pi 4.

here's the output from load until the second screenshot:

2020/09/16,16:56:29.071,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,16:56:29.071,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=259 duration=1.01646 average_per_call=0.00392455"
2020/09/16,16:56:29.071,opengl_Wrapper.cpp:107,ERROR, "glLinkProgram: call_count=39 duration=0.798517 average_per_call=0.0204748"
2020/09/16,16:56:29.071,opengl_Wrapper.cpp:107,ERROR, "GlReadPixelsAync: call_count=100 duration=0.632313 average_per_call=0.00632313"
2020/09/16,16:56:29.071,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_Init: call_count=1 duration=0.614122 average_per_call=0.614122"
2020/09/16,16:56:29.071,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=25102 duration=0.474642 average_per_call=1.89085e-05"
2020/09/16,16:56:29.071,opengl_Wrapper.cpp:107,ERROR, "glCompileShader: call_count=52 duration=0.304164 average_per_call=0.0058493"
2020/09/16,16:56:29.071,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=582 duration=0.0940204 average_per_call=0.000161547"
2020/09/16,16:56:29.071,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=319 duration=0.0918973 average_per_call=0.000288079"
2020/09/16,16:56:29.071,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=74621 duration=0.0458903 average_per_call=6.14979e-07"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=111 duration=0.0391397 average_per_call=0.00035261"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=408 duration=0.0348587 average_per_call=8.5438e-05"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_SetVideoMode: call_count=1 duration=0.0335926 average_per_call=0.0335926"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=74621 duration=0.0235238 average_per_call=3.15244e-07"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=34920 duration=0.022847 average_per_call=6.54267e-07"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=1217 duration=0.00479936 average_per_call=3.9436e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=1171 duration=0.00473869 average_per_call=4.0467e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glGetUniformLocation: call_count=1700 duration=0.00378804 average_per_call=2.22826e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glBufferStorage: call_count=4 duration=0.00344067 average_per_call=0.000860167"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glBufferData: call_count=1 duration=0.00208962 average_per_call=0.00208962"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=1186 duration=0.0013 average_per_call=1.09612e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=1186 duration=0.00127976 average_per_call=1.07906e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=644 duration=0.00121869 average_per_call=1.89238e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glBindBuffer: call_count=208 duration=0.00100279 average_per_call=4.82111e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glGetStringi: call_count=764 duration=0.000901242 average_per_call=1.17964e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=111 duration=0.000846608 average_per_call=7.6271e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glShaderSource: call_count=52 duration=0.00074911 average_per_call=1.4406e-05"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=594 duration=0.000659969 average_per_call=1.11106e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=436 duration=0.000512347 average_per_call=1.17511e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=588 duration=0.000510917 average_per_call=8.68906e-07"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=438 duration=0.00044729 average_per_call=1.02121e-06"
2020/09/16,16:56:29.072,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=198 duration=0.000418086 average_per_call=2.11155e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=217 duration=0.000386311 average_per_call=1.78024e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glCreateProgram: call_count=39 duration=0.000362734 average_per_call=9.30087e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glCreateShader: call_count=52 duration=0.000358417 average_per_call=6.89263e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glBindAttribLocation: call_count=154 duration=0.000219512 average_per_call=1.4254e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glGetProgramiv: call_count=39 duration=0.000216831 average_per_call=5.55977e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glGetShaderiv: call_count=70 duration=0.00021031 average_per_call=3.00443e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glAttachShader: call_count=78 duration=0.000187587 average_per_call=2.40496e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=59 duration=0.000161349 average_per_call=2.73473e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glFramebufferTexture2D: call_count=14 duration=0.000142795 average_per_call=1.01996e-05"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glDeleteShader: call_count=48 duration=0.000129809 average_per_call=2.70435e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glMapBufferRange: call_count=4 duration=0.000115405 average_per_call=2.88512e-05"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glDeleteTextures: call_count=7 duration=6.8627e-05 average_per_call=9.80386e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glVertexAttribPointer: call_count=64 duration=5.8434e-05 average_per_call=9.13031e-07"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glGetString: call_count=3 duration=4.4146e-05 average_per_call=1.47153e-05"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glUniform2i: call_count=55 duration=3.9758e-05 average_per_call=7.22873e-07"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glGenFramebuffers: call_count=11 duration=3.8277e-05 average_per_call=3.47973e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glUniform1f: call_count=39 duration=3.7743e-05 average_per_call=9.67769e-07"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glGetIntegerv: call_count=17 duration=2.7036e-05 average_per_call=1.59035e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glDeleteFramebuffers: call_count=5 duration=2.5831e-05 average_per_call=5.1662e-06"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glPolygonOffset: call_count=1 duration=1.9092e-05 average_per_call=1.9092e-05"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glDeleteBuffers: call_count=1 duration=1.5111e-05 average_per_call=1.5111e-05"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glDebugMessageCallback: call_count=1 duration=1.4407e-05 average_per_call=1.4407e-05"
2020/09/16,16:56:29.073,opengl_Wrapper.cpp:107,ERROR, "glGenBuffers: call_count=3 duration=1.2258e-05 average_per_call=4.086e-06"
2020/09/16,16:56:29.074,opengl_Wrapper.cpp:107,ERROR, "glGetError: call_count=4 duration=7.593e-06 average_per_call=1.89825e-06"
2020/09/16,16:56:29.074,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SetAttribute: call_count=7 duration=6.593e-06 average_per_call=9.41857e-07"
2020/09/16,16:56:29.074,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=1 duration=3.648e-06 average_per_call=3.648e-06"
2020/09/16,16:56:29.074,opengl_Wrapper.cpp:107,ERROR, "glDebugMessageControl: call_count=1 duration=3.518e-06 average_per_call=3.518e-06"
2020/09/16,16:56:29.074,opengl_Wrapper.cpp:107,ERROR, "glGetFloatv: call_count=1 duration=3.351e-06 average_per_call=3.351e-06"
2020/09/16,16:56:29.074,opengl_Wrapper.cpp:107,ERROR, "glPixelStorei: call_count=2 duration=2.297e-06 average_per_call=1.1485e-06"
2020/09/16,16:56:29.074,opengl_Wrapper.cpp:107,ERROR, "glCullFace: call_count=1 duration=1.759e-06 average_per_call=1.759e-06"
2020/09/16,16:56:29.074,opengl_Wrapper.cpp:107,ERROR, "glDepthMask: call_count=1 duration=1.722e-06 average_per_call=1.722e-06"
2020/09/16,16:56:29.074,opengl_Wrapper.cpp:107,ERROR, "glDepthFunc: call_count=1 duration=1.148e-06 average_per_call=1.148e-06"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:107,ERROR, "GlReadPixelsAync: call_count=513 duration=3.16403 average_per_call=0.00616769"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=39420 duration=0.518735 average_per_call=1.31592e-05"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=24560 duration=0.509296 average_per_call=2.07368e-05"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=512 duration=0.27511 average_per_call=0.000537324"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=91547 duration=0.0611114 average_per_call=6.67542e-07"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=1024 duration=0.0562951 average_per_call=5.49757e-05"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=91547 duration=0.0309826 average_per_call=3.38434e-07"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=32401 duration=0.0210233 average_per_call=6.48848e-07"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=3585 duration=0.0155166 average_per_call=4.3282e-06"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=3667 duration=0.0138757 average_per_call=3.78393e-06"
2020/09/16,16:56:39.079,opengl_Wrapper.cpp:107,ERROR, "glBindBuffer: call_count=1025 duration=0.00511865 average_per_call=4.99381e-06"
2020/09/16,16:56:39.080,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=3472 duration=0.00386529 average_per_call=1.11328e-06"
2020/09/16,16:56:39.080,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=2042 duration=0.00362046 average_per_call=1.773e-06"
2020/09/16,16:56:39.080,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=3474 duration=0.00356709 average_per_call=1.0268e-06"
2020/09/16,16:56:39.080,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=3155 duration=0.00320235 average_per_call=1.01501e-06"
2020/09/16,16:56:39.080,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=3157 duration=0.00297922 average_per_call=9.43687e-07"
2020/09/16,16:56:39.080,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=1025 duration=0.00250529 average_per_call=2.44419e-06"
2020/09/16,16:56:39.080,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1026 duration=0.00119254 average_per_call=1.16232e-06"
2020/09/16,16:56:39.080,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=1 duration=3.4073e-05 average_per_call=3.4073e-05"
2020/09/16,16:56:39.080,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=1 duration=3.2388e-05 average_per_call=3.2388e-05"
2020/09/16,16:56:39.080,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=1 duration=1.1667e-05 average_per_call=1.1667e-05"
2020/09/16,16:56:39.080,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=5 duration=6.148e-06 average_per_call=1.2296e-06"
2020/09/16,16:56:49.082,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "GlReadPixelsAync: call_count=569 duration=3.53035 average_per_call=0.00620447"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=568 duration=0.570823 average_per_call=0.00100497"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=16584 duration=0.293649 average_per_call=1.77068e-05"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=1704 duration=0.224693 average_per_call=0.000131862"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=1136 duration=0.0613198 average_per_call=5.39787e-05"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=3980 duration=0.0167814 average_per_call=4.21643e-06"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=3572 duration=0.0134004 average_per_call=3.7515e-06"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=9972 duration=0.0121903 average_per_call=1.22245e-06"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glBindBuffer: call_count=1139 duration=0.0056737 average_per_call=4.9813e-06"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=9972 duration=0.00532729 average_per_call=5.34225e-07"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=2256 duration=0.00399859 average_per_call=1.77243e-06"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=3202 duration=0.00345666 average_per_call=1.07953e-06"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=2780 duration=0.00344303 average_per_call=1.2385e-06"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=1763 duration=0.00340986 average_per_call=1.93413e-06"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=2778 duration=0.00328498 average_per_call=1.1825e-06"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=3203 duration=0.00328113 average_per_call=1.02439e-06"
2020/09/16,16:56:49.083,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=1136 duration=0.002638 average_per_call=2.32218e-06"
2020/09/16,16:56:49.084,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1137 duration=0.00137724 average_per_call=1.2113e-06"
2020/09/16,16:56:49.084,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=602 duration=0.0013233 average_per_call=2.19817e-06"
2020/09/16,16:56:49.084,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=6 duration=0.000160905 average_per_call=2.68175e-05"
2020/09/16,16:56:49.084,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=6 duration=0.000137332 average_per_call=2.28887e-05"
2020/09/16,16:56:49.084,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=6 duration=0.00010322 average_per_call=1.72033e-05"
2020/09/16,16:56:49.084,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=30 duration=2.7738e-05 average_per_call=9.246e-07"
2020/09/16,16:56:49.084,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=10 duration=1.1798e-05 average_per_call=1.1798e-06"
2020/09/16,16:56:49.084,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=1 duration=4.499e-06 average_per_call=4.499e-06"
2020/09/16,16:57:02.855,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "GlReadPixelsAync: call_count=396 duration=3.29019 average_per_call=0.00830856"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=49830 duration=0.967544 average_per_call=1.94169e-05"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=8493 duration=0.348592 average_per_call=4.10446e-05"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=397 duration=0.204372 average_per_call=0.000514791"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=150238 duration=0.101792 average_per_call=6.77541e-07"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=40801 duration=0.0477734 average_per_call=1.17089e-06"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=150238 duration=0.0466684 average_per_call=3.1063e-07"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=794 duration=0.0434741 average_per_call=5.47532e-05"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=349 duration=0.0387089 average_per_call=0.000110914"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=357 duration=0.0122901 average_per_call=3.44262e-05"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=2777 duration=0.0119732 average_per_call=4.31157e-06"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=2087 duration=0.00882606 average_per_call=4.22907e-06"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=7915 duration=0.00529227 average_per_call=6.68638e-07"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glBindBuffer: call_count=792 duration=0.00422148 average_per_call=5.33016e-06"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=2399 duration=0.00276778 average_per_call=1.15372e-06"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=1364 duration=0.00266953 average_per_call=1.95713e-06"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=2398 duration=0.0024895 average_per_call=1.03816e-06"
2020/09/16,16:57:03.142,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=1757 duration=0.0022044 average_per_call=1.25464e-06"
2020/09/16,16:57:03.143,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=1757 duration=0.00218217 average_per_call=1.24198e-06"
2020/09/16,16:57:03.143,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=793 duration=0.00205907 average_per_call=2.59656e-06"
2020/09/16,16:57:03.143,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=372 duration=0.00168592 average_per_call=4.53205e-06"
2020/09/16,16:57:03.143,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=349 duration=0.00141682 average_per_call=4.05965e-06"
2020/09/16,16:57:03.143,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1411 duration=0.00141293 average_per_call=1.00137e-06"
2020/09/16,16:57:03.143,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=1745 duration=0.00130455 average_per_call=7.47593e-07"
2020/09/16,16:57:03.143,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=55 duration=0.000210389 average_per_call=3.82525e-06"
2020/09/16,16:57:03.143,opengl_Wrapper.cpp:107,ERROR, "glPixelStorei: call_count=16 duration=2.0113e-05 average_per_call=1.25706e-06"

dankcushions commented 4 years ago

"glBindTexture: call_count=150238 duration=0.101792 average_per_call=6.77541e-07"

this seems a little strange. why so many expensive glBindTextures? this seems to be have been mentioned before by @loganmc10 here, so maybe not an issue, but 150,000 seems like a lot for a static screen, to my untrained eye!

EDIT, actually maybe since the duration is so small, it's not an issue. not really sure how to read profiling data....

loganmc10 commented 4 years ago

I think duration is meant to be read the total time spent performing that operation, so yeah a small duration should mean it's not spending much time on that.

From that output it seems like the most time is spent doing GlReadPixelsAync, you might try disabling color buffer copies and see what happens, although I assume you might have already tried that.

fzurita commented 4 years ago

GlReadPixelsAync seems to be really expensive in your platform even in async mode, so turning that off "copy color buffer to RDRAM" should help, and I don't think that game needs it.

CoreVideo_GL_SwapBuffers seems to be really expensive. I don't know why this would be so expensive unless you have vsync on and somehow the driver is actually blocking until the swapping is complete in the display itself. I'm surprised the driver can't queue them up.

After that glDrawArraysUnbuffered and glDrawElementsUnbuffered seem to be the next big hitters. I'm not sure what could be done to optimize that, but the high number of calls to those two seem to be troublesome. GL_EXT_buffer_storage extension would help in that case. I think the high number of glDrawArrays calls is probably a side effect of the 2D scene being rendered.

Duration is how long over a period of 10 seconds the driver spent on that call. Count is the total number of calls performed over 10 seconds.

loganmc10 commented 4 years ago

From what I remember, and it's been a while since I did any OpenGL programming, things like GL_SwapBuffers can be a bit misleading, because the driver might queue up some previously specified actions until SwapBuffers is called, so it's actually kind of hard to determine why that call is taking the time it is. The same goes for glDrawArraysUnbuffered, that call is basically saying "now draw all the things I told you about", so it can be a little challenging to determine what the underlying cause could be.

However the general rule with GL programming is to reduce the number of glDraw and glBind calls as much as possible, in order to give the GPU more opportunities to batch operations together and make use of the parallelism available to GPUs

dankcushions commented 4 years ago

GlReadPixelsAync seems to be really expensive in your platform even in async mode, so turning that off "copy color buffer to RDRAM" should help, and I don't think that game needs it.

It was at 2, but I tried:

# Enable color buffer copy to RDRAM (0=do not copy, 1=copy in sync mode, 2=Double Buffer, 3=Triple Buffer)
EnableCopyColorToRDRAM = 0

It didn't seem to be any different. this is the new log, which doesn't show a decrease in use for GlReadPixelsAync:

2020/09/16,17:25:16.026,opengl_Utils.cpp:60,WARNING, "Could not query EGL extensions on this device"
2020/09/16,17:25:16.027,opengl_Utils.cpp:60,WARNING, "Could not query EGL extensions on this device"
2020/09/16,17:25:25.378,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,17:25:25.378,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=299 duration=1.32334 average_per_call=0.00442588"
2020/09/16,17:25:25.378,opengl_Wrapper.cpp:107,ERROR, "glLinkProgram: call_count=39 duration=0.798196 average_per_call=0.0204666"
2020/09/16,17:25:25.378,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=35396 duration=0.640323 average_per_call=1.80903e-05"
2020/09/16,17:25:25.378,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_Init: call_count=1 duration=0.613117 average_per_call=0.613117"
2020/09/16,17:25:25.378,opengl_Wrapper.cpp:107,ERROR, "glCompileShader: call_count=52 duration=0.30508 average_per_call=0.00586691"
2020/09/16,17:25:25.378,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=828 duration=0.099666 average_per_call=0.00012037"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=319 duration=0.097023 average_per_call=0.000304147"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=105470 duration=0.0618722 average_per_call=5.86633e-07"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=109 duration=0.0391012 average_per_call=0.000358727"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=488 duration=0.0353387 average_per_call=7.24154e-05"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_SetVideoMode: call_count=1 duration=0.0335694 average_per_call=0.0335694"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=49238 duration=0.0305496 average_per_call=6.20448e-07"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=105470 duration=0.0290191 average_per_call=2.75141e-07"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=1542 duration=0.00579614 average_per_call=3.75885e-06"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=1167 duration=0.00452284 average_per_call=3.87561e-06"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glGetUniformLocation: call_count=1700 duration=0.00381847 average_per_call=2.24616e-06"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glBufferData: call_count=1 duration=0.00211728 average_per_call=0.00211728"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=1469 duration=0.00149632 average_per_call=1.0186e-06"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=807 duration=0.00143057 average_per_call=1.77271e-06"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=1467 duration=0.00135164 average_per_call=9.21363e-07"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glGetStringi: call_count=764 duration=0.000890441 average_per_call=1.1655e-06"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=109 duration=0.000808523 average_per_call=7.41764e-06"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=840 duration=0.000739777 average_per_call=8.80687e-07"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glShaderSource: call_count=52 duration=0.000686407 average_per_call=1.32001e-05"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=834 duration=0.000598253 average_per_call=7.1733e-07"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=436 duration=0.000545308 average_per_call=1.25071e-06"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=279 duration=0.00054066 average_per_call=1.93785e-06"
2020/09/16,17:25:25.379,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=434 duration=0.000394758 average_per_call=9.09581e-07"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=297 duration=0.000384964 average_per_call=1.29618e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glCreateShader: call_count=52 duration=0.000332008 average_per_call=6.38477e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glCreateProgram: call_count=39 duration=0.000306124 average_per_call=7.84933e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glGetProgramiv: call_count=39 duration=0.000218553 average_per_call=5.60392e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glBindAttribLocation: call_count=154 duration=0.000214904 average_per_call=1.39548e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glGetShaderiv: call_count=70 duration=0.000203792 average_per_call=2.91131e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glAttachShader: call_count=78 duration=0.000181127 average_per_call=2.32214e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=59 duration=0.000157628 average_per_call=2.67166e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glDeleteShader: call_count=48 duration=0.000127391 average_per_call=2.65398e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glFramebufferTexture2D: call_count=12 duration=0.000114423 average_per_call=9.53525e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glDeleteTextures: call_count=6 duration=6.7369e-05 average_per_call=1.12282e-05"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glVertexAttribPointer: call_count=62 duration=5.7977e-05 average_per_call=9.35113e-07"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glUniform1f: call_count=39 duration=4.0835e-05 average_per_call=1.04705e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glUniform2i: call_count=55 duration=3.991e-05 average_per_call=7.25636e-07"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glGenFramebuffers: call_count=11 duration=3.67e-05 average_per_call=3.33636e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glGetIntegerv: call_count=17 duration=2.8146e-05 average_per_call=1.65565e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glDeleteFramebuffers: call_count=5 duration=2.8091e-05 average_per_call=5.6182e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glGetString: call_count=3 duration=2.7555e-05 average_per_call=9.185e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glPolygonOffset: call_count=1 duration=1.9851e-05 average_per_call=1.9851e-05"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glDebugMessageCallback: call_count=1 duration=1.7444e-05 average_per_call=1.7444e-05"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glBindBuffer: call_count=2 duration=8.129e-06 average_per_call=4.0645e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "glGetError: call_count=4 duration=6.796e-06 average_per_call=1.699e-06"
2020/09/16,17:25:25.380,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SetAttribute: call_count=7 duration=6.129e-06 average_per_call=8.75571e-07"
2020/09/16,17:25:25.381,opengl_Wrapper.cpp:107,ERROR, "glDebugMessageControl: call_count=1 duration=3.685e-06 average_per_call=3.685e-06"
2020/09/16,17:25:25.381,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=1 duration=3.556e-06 average_per_call=3.556e-06"
2020/09/16,17:25:25.381,opengl_Wrapper.cpp:107,ERROR, "glGetFloatv: call_count=1 duration=2.814e-06 average_per_call=2.814e-06"
2020/09/16,17:25:25.381,opengl_Wrapper.cpp:107,ERROR, "glGenBuffers: call_count=1 duration=2.334e-06 average_per_call=2.334e-06"
2020/09/16,17:25:25.381,opengl_Wrapper.cpp:107,ERROR, "glPixelStorei: call_count=2 duration=2.11e-06 average_per_call=1.055e-06"
2020/09/16,17:25:25.381,opengl_Wrapper.cpp:107,ERROR, "glDepthMask: call_count=1 duration=1.722e-06 average_per_call=1.722e-06"
2020/09/16,17:25:25.381,opengl_Wrapper.cpp:107,ERROR, "glCullFace: call_count=1 duration=1.685e-06 average_per_call=1.685e-06"
2020/09/16,17:25:25.381,opengl_Wrapper.cpp:107,ERROR, "glDepthFunc: call_count=1 duration=1.092e-06 average_per_call=1.092e-06"
2020/09/16,17:25:35.392,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=594 duration=6.16517 average_per_call=0.0103791"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=47716 duration=0.645842 average_per_call=1.35351e-05"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=14632 duration=0.364045 average_per_call=2.48801e-05"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=1188 duration=0.0587058 average_per_call=4.94157e-05"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=65480 duration=0.0432885 average_per_call=6.61095e-07"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=65480 duration=0.0198626 average_per_call=3.03339e-07"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=4184 duration=0.0145051 average_per_call=3.46681e-06"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=2971 duration=0.0122569 average_per_call=4.12553e-06"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=18331 duration=0.0117158 average_per_call=6.39123e-07"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=2359 duration=0.00392789 average_per_call=1.66506e-06"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=3981 duration=0.00361595 average_per_call=9.08302e-07"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=3598 duration=0.00341844 average_per_call=9.50093e-07"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=3982 duration=0.00318501 average_per_call=7.99851e-07"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=3599 duration=0.0029466 average_per_call=8.18727e-07"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=1188 duration=0.00209254 average_per_call=1.76139e-06"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1188 duration=0.00124146 average_per_call=1.045e-06"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=113 duration=0.000256106 average_per_call=2.26642e-06"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=7 duration=0.000204163 average_per_call=2.91661e-05"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=7 duration=0.00018094 average_per_call=2.58486e-05"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=7 duration=8.9201e-05 average_per_call=1.2743e-05"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=35 duration=7.0407e-05 average_per_call=2.01163e-06"
2020/09/16,17:25:35.393,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=8 duration=9.406e-06 average_per_call=1.17575e-06"
2020/09/16,17:25:35.394,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=1 duration=3.889e-06 average_per_call=3.889e-06"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=571 duration=1.35882 average_per_call=0.00237972"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=25163 duration=0.632333 average_per_call=2.51295e-05"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=8214 duration=0.137583 average_per_call=1.67498e-05"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=1142 duration=0.0705203 average_per_call=6.17516e-05"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=74964 duration=0.0516734 average_per_call=6.8931e-07"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=299 duration=0.0312889 average_per_call=0.000104645"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=20156 duration=0.023473 average_per_call=1.16457e-06"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=74964 duration=0.0212853 average_per_call=2.8394e-07"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=3355 duration=0.0118262 average_per_call=3.52494e-06"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=2855 duration=0.0116356 average_per_call=4.07551e-06"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=299 duration=0.00975176 average_per_call=3.26146e-05"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=2121 duration=0.00353636 average_per_call=1.66731e-06"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=3181 duration=0.00312387 average_per_call=9.82041e-07"
2020/09/16,17:25:45.394,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=1521 duration=0.00289889 average_per_call=1.90591e-06"
2020/09/16,17:25:45.395,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=3180 duration=0.00264451 average_per_call=8.31607e-07"
2020/09/16,17:25:45.395,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=2293 duration=0.00245375 average_per_call=1.07011e-06"
2020/09/16,17:25:45.395,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=2292 duration=0.00223294 average_per_call=9.74231e-07"
2020/09/16,17:25:45.395,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=1142 duration=0.00209768 average_per_call=1.83685e-06"
2020/09/16,17:25:45.395,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1533 duration=0.0013211 average_per_call=8.61776e-07"
2020/09/16,17:25:45.395,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=299 duration=0.00118455 average_per_call=3.96171e-06"
2020/09/16,17:25:45.395,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=1495 duration=0.00102821 average_per_call=6.87767e-07"
2020/09/16,17:25:45.395,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=4 duration=4.76e-06 average_per_call=1.19e-06"
2020/09/16,17:25:55.395,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,17:25:55.395,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=120067 duration=2.83675 average_per_call=2.36264e-05"
2020/09/16,17:25:55.395,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=394 duration=1.15224 average_per_call=0.00292446"
2020/09/16,17:25:55.395,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=43192 duration=0.894805 average_per_call=2.07169e-05"
2020/09/16,17:25:55.395,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=416591 duration=0.272095 average_per_call=6.53146e-07"
2020/09/16,17:25:55.395,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=416591 duration=0.116522 average_per_call=2.79703e-07"
2020/09/16,17:25:55.395,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=100573 duration=0.115528 average_per_call=1.14869e-06"
2020/09/16,17:25:55.395,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=788 duration=0.0407795 average_per_call=5.17507e-05"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=61943 duration=0.0335183 average_per_call=5.41115e-07"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=119 duration=0.0179306 average_per_call=0.000150677"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=3478 duration=0.0141725 average_per_call=4.0749e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=1970 duration=0.00987528 average_per_call=5.01283e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=123 duration=0.006141 average_per_call=4.99268e-05"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=3133 duration=0.00351516 average_per_call=1.12198e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=1524 duration=0.0034638 average_per_call=2.27283e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=3133 duration=0.00330375 average_per_call=1.0545e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=2573 duration=0.00314874 average_per_call=1.22376e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=2573 duration=0.00266151 average_per_call=1.0344e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=678 duration=0.00251632 average_per_call=3.71139e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=788 duration=0.00174201 average_per_call=2.21067e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1568 duration=0.00121442 average_per_call=7.74501e-07"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=119 duration=0.000836139 average_per_call=7.02638e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=595 duration=0.00061928 average_per_call=1.04081e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=14 duration=1.4595e-05 average_per_call=1.0425e-06"
2020/09/16,17:25:55.396,opengl_Wrapper.cpp:107,ERROR, "glPixelStorei: call_count=12 duration=1.3482e-05 average_per_call=1.1235e-06"

CoreVideo_GL_SwapBuffers seems to be really expensive. I don't know why this would be so expensive unless you have vsync on and somehow the driver is actually blocking until the swapping is complete in the display itself. I'm surprised the driver can't queue them up.

vsync is on in my case. I tried it off and it seemed even slower! however I know there are some strange things with vsync and the Pi 4's MESA drivers, but I recall this slowdown pre-dating MESA on pi3. in the log, it seems to increase the CoreVideo_GL_SwapBuffers cost:

2020/09/16,17:31:43.035,opengl_Utils.cpp:60,WARNING, "Could not query EGL extensions on this device"
2020/09/16,17:31:43.035,opengl_Utils.cpp:60,WARNING, "Could not query EGL extensions on this device"
2020/09/16,17:31:52.382,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,17:31:52.382,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=227 duration=3.07467 average_per_call=0.0135448"
2020/09/16,17:31:52.395,opengl_Wrapper.cpp:107,ERROR, "glLinkProgram: call_count=39 duration=0.795116 average_per_call=0.0203876"
2020/09/16,17:31:52.395,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_Init: call_count=1 duration=0.624577 average_per_call=0.624577"
2020/09/16,17:31:52.395,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=16910 duration=0.334771 average_per_call=1.97972e-05"
2020/09/16,17:31:52.395,opengl_Wrapper.cpp:107,ERROR, "glCompileShader: call_count=52 duration=0.300545 average_per_call=0.00577971"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=319 duration=0.0958711 average_per_call=0.000300536"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=390 duration=0.0870412 average_per_call=0.000223183"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=109 duration=0.0354491 average_per_call=0.000325221"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_SetVideoMode: call_count=1 duration=0.0347083 average_per_call=0.0347083"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=344 duration=0.0313263 average_per_call=9.1065e-05"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=50075 duration=0.0304247 average_per_call=6.07583e-07"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=50075 duration=0.0157994 average_per_call=3.15514e-07"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=23528 duration=0.0148389 average_per_call=6.3069e-07"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glGetUniformLocation: call_count=1700 duration=0.00372961 average_per_call=2.19389e-06"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=961 duration=0.0034966 average_per_call=3.6385e-06"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=805 duration=0.00282836 average_per_call=3.51348e-06"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glBufferData: call_count=1 duration=0.00207447 average_per_call=0.00207447"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=962 duration=0.00110774 average_per_call=1.1515e-06"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=962 duration=0.00100666 average_per_call=1.04643e-06"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=516 duration=0.00096279 average_per_call=1.86587e-06"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glGetStringi: call_count=764 duration=0.000893947 average_per_call=1.17009e-06"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=109 duration=0.000764228 average_per_call=7.01127e-06"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=436 duration=0.000563302 average_per_call=1.29198e-06"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glShaderSource: call_count=52 duration=0.000484218 average_per_call=9.31188e-06"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=434 duration=0.000429681 average_per_call=9.90048e-07"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=402 duration=0.000342561 average_per_call=8.52142e-07"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glCreateProgram: call_count=39 duration=0.000329711 average_per_call=8.45413e-06"
2020/09/16,17:31:52.396,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=396 duration=0.000289033 average_per_call=7.29881e-07"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glCreateShader: call_count=52 duration=0.000285548 average_per_call=5.49131e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=151 duration=0.000250418 average_per_call=1.6584e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=133 duration=0.000230661 average_per_call=1.73429e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glGetProgramiv: call_count=39 duration=0.000224436 average_per_call=5.75477e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glGetShaderiv: call_count=70 duration=0.000220068 average_per_call=3.14383e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glBindAttribLocation: call_count=154 duration=0.00021697 average_per_call=1.4089e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glAttachShader: call_count=78 duration=0.000185256 average_per_call=2.37508e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=59 duration=0.000158791 average_per_call=2.69137e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glDeleteShader: call_count=48 duration=0.00013213 average_per_call=2.75271e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glFramebufferTexture2D: call_count=12 duration=0.000108145 average_per_call=9.01208e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glDeleteTextures: call_count=6 duration=5.9981e-05 average_per_call=9.99683e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glVertexAttribPointer: call_count=62 duration=4.6481e-05 average_per_call=7.49694e-07"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glUniform1f: call_count=39 duration=4.2478e-05 average_per_call=1.08918e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glUniform2i: call_count=55 duration=4.1122e-05 average_per_call=7.47673e-07"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glGenFramebuffers: call_count=11 duration=3.5369e-05 average_per_call=3.21536e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glGetIntegerv: call_count=17 duration=2.9019e-05 average_per_call=1.707e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glDeleteFramebuffers: call_count=5 duration=2.3703e-05 average_per_call=4.7406e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glGetString: call_count=3 duration=2.0648e-05 average_per_call=6.88267e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glPolygonOffset: call_count=1 duration=1.9352e-05 average_per_call=1.9352e-05"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glDebugMessageCallback: call_count=1 duration=1.4703e-05 average_per_call=1.4703e-05"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glGetError: call_count=4 duration=9.5e-06 average_per_call=2.375e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "glBindBuffer: call_count=2 duration=7.444e-06 average_per_call=3.722e-06"
2020/09/16,17:31:52.397,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SetAttribute: call_count=7 duration=6.333e-06 average_per_call=9.04714e-07"
2020/09/16,17:31:52.398,opengl_Wrapper.cpp:107,ERROR, "glDebugMessageControl: call_count=1 duration=3.871e-06 average_per_call=3.871e-06"
2020/09/16,17:31:52.398,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=1 duration=3.704e-06 average_per_call=3.704e-06"
2020/09/16,17:31:52.398,opengl_Wrapper.cpp:107,ERROR, "glGetFloatv: call_count=1 duration=2.962e-06 average_per_call=2.962e-06"
2020/09/16,17:31:52.398,opengl_Wrapper.cpp:107,ERROR, "glPixelStorei: call_count=2 duration=2.296e-06 average_per_call=1.148e-06"
2020/09/16,17:31:52.398,opengl_Wrapper.cpp:107,ERROR, "glGenBuffers: call_count=1 duration=2.166e-06 average_per_call=2.166e-06"
2020/09/16,17:31:52.398,opengl_Wrapper.cpp:107,ERROR, "glCullFace: call_count=1 duration=1.629e-06 average_per_call=1.629e-06"
2020/09/16,17:31:52.398,opengl_Wrapper.cpp:107,ERROR, "glDepthMask: call_count=1 duration=1.537e-06 average_per_call=1.537e-06"
2020/09/16,17:31:52.398,opengl_Wrapper.cpp:107,ERROR, "glDepthFunc: call_count=1 duration=1.074e-06 average_per_call=1.074e-06"
2020/09/16,17:32:02.398,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,17:32:02.398,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=522 duration=6.80357 average_per_call=0.0130337"
2020/09/16,17:32:02.398,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=32685 duration=0.612037 average_per_call=1.87253e-05"
2020/09/16,17:32:02.398,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=37473 duration=0.450774 average_per_call=1.20293e-05"
2020/09/16,17:32:02.398,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=114897 duration=0.0723011 average_per_call=6.29269e-07"
2020/09/16,17:32:02.398,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=1044 duration=0.0443549 average_per_call=4.24855e-05"
2020/09/16,17:32:02.398,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=114897 duration=0.0363485 average_per_call=3.16357e-07"
2020/09/16,17:32:02.398,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=43793 duration=0.0272976 average_per_call=6.23333e-07"
2020/09/16,17:32:02.398,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=3765 duration=0.0118143 average_per_call=3.13793e-06"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=2610 duration=0.0099842 average_per_call=3.82536e-06"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=2080 duration=0.00334378 average_per_call=1.60758e-06"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=3247 duration=0.00322232 average_per_call=9.92398e-07"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=3507 duration=0.00290743 average_per_call=8.29036e-07"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=3247 duration=0.0027506 average_per_call=8.47119e-07"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=3507 duration=0.00264662 average_per_call=7.54667e-07"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=1044 duration=0.0017812 average_per_call=1.70613e-06"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1044 duration=0.00103868 average_per_call=9.94899e-07"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=1 duration=3.3888e-05 average_per_call=3.3888e-05"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=1 duration=3.274e-05 average_per_call=3.274e-05"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=1 duration=1.3259e-05 average_per_call=1.3259e-05"
2020/09/16,17:32:02.399,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=5 duration=6e-06 average_per_call=1.2e-06"
2020/09/16,17:32:12.399,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=575 duration=7.86706 average_per_call=0.0136818"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=18663 duration=0.301272 average_per_call=1.61427e-05"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=1726 duration=0.203598 average_per_call=0.000117959"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=1150 duration=0.0474265 average_per_call=4.12405e-05"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=11076 duration=0.0111321 average_per_call=1.00506e-06"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=3655 duration=0.0110321 average_per_call=3.01835e-06"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=2879 duration=0.010081 average_per_call=3.50156e-06"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=11076 duration=0.00494356 average_per_call=4.46331e-07"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=3261 duration=0.00346249 average_per_call=1.06179e-06"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=2286 duration=0.00345815 average_per_call=1.51275e-06"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=1763 duration=0.00277623 average_per_call=1.57472e-06"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=2877 duration=0.00265048 average_per_call=9.21264e-07"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=3260 duration=0.00250423 average_per_call=7.6817e-07"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=2877 duration=0.00235937 average_per_call=8.20079e-07"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=1152 duration=0.0019315 average_per_call=1.67665e-06"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1153 duration=0.00115556 average_per_call=1.00222e-06"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=602 duration=0.00113818 average_per_call=1.89067e-06"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=6 duration=0.000153681 average_per_call=2.56135e-05"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=6 duration=0.000135813 average_per_call=2.26355e-05"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=6 duration=6.5387e-05 average_per_call=1.08978e-05"
2020/09/16,17:32:12.400,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=30 duration=2.8612e-05 average_per_call=9.53733e-07"
2020/09/16,17:32:12.401,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=10 duration=1.1294e-05 average_per_call=1.1294e-06"
2020/09/16,17:32:12.401,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=1 duration=3.999e-06 average_per_call=3.999e-06"
2020/09/16,17:32:22.414,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,17:32:22.414,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=302 duration=5.40279 average_per_call=0.01789"
2020/09/16,17:32:22.414,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=73536 duration=1.299 average_per_call=1.76648e-05"
2020/09/16,17:32:22.414,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=13496 duration=0.408672 average_per_call=3.02809e-05"
2020/09/16,17:32:22.414,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=234407 duration=0.151804 average_per_call=6.4761e-07"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=60946 duration=0.0726539 average_per_call=1.1921e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=234407 duration=0.0703565 average_per_call=3.00147e-07"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=604 duration=0.0386738 average_per_call=6.40295e-05"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=378 duration=0.0357557 average_per_call=9.45919e-05"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=382 duration=0.0119762 average_per_call=3.13514e-05"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=19021 duration=0.0102135 average_per_call=5.36958e-07"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=1872 duration=0.00728726 average_per_call=3.89276e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=1507 duration=0.006683 average_per_call=4.43464e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=2053 duration=0.00223488 average_per_call=1.08859e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=2054 duration=0.00210578 average_per_call=1.02521e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=1000 duration=0.00200015 average_per_call=2.00015e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=1276 duration=0.00162819 average_per_call=1.27601e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=378 duration=0.00149294 average_per_call=3.94959e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=1890 duration=0.00140774 average_per_call=7.44835e-07"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=1276 duration=0.00140451 average_per_call=1.10071e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1772 duration=0.00121997 average_per_call=6.88471e-07"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=602 duration=0.0010721 average_per_call=1.7809e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=213 duration=0.000779763 average_per_call=3.66086e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glPixelStorei: call_count=12 duration=1.474e-05 average_per_call=1.22833e-06"
2020/09/16,17:32:22.415,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=11 duration=1.3112e-05 average_per_call=1.192e-06"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=243 duration=5.1727 average_per_call=0.0212868"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=71544 duration=1.25083 average_per_call=1.74834e-05"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=30444 duration=0.489063 average_per_call=1.60644e-05"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=256137 duration=0.168261 average_per_call=6.56919e-07"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=256137 duration=0.0785864 average_per_call=3.06814e-07"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=60243 duration=0.0721082 average_per_call=1.19696e-06"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=43668 duration=0.0232348 average_per_call=5.32079e-07"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=486 duration=0.0219684 average_per_call=4.52025e-05"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=40 duration=0.0138765 average_per_call=0.000346913"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=2372 duration=0.00877319 average_per_call=3.69865e-06"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=1215 duration=0.00607934 average_per_call=5.00357e-06"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=40 duration=0.00426638 average_per_call=0.00010666"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=1916 duration=0.00239511 average_per_call=1.25006e-06"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=958 duration=0.00213696 average_per_call=2.23065e-06"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=1916 duration=0.00210623 average_per_call=1.09929e-06"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=1659 duration=0.00172802 average_per_call=1.0416e-06"
2020/09/16,17:32:32.431,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=472 duration=0.00168499 average_per_call=3.56989e-06"
2020/09/16,17:32:32.432,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=1659 duration=0.0016607 average_per_call=1.00103e-06"
2020/09/16,17:32:32.432,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=486 duration=0.00103174 average_per_call=2.12291e-06"
2020/09/16,17:32:32.432,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=486 duration=0.000513373 average_per_call=1.05632e-06"
2020/09/16,17:32:32.432,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=40 duration=0.000432232 average_per_call=1.08058e-05"
2020/09/16,17:32:32.432,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=200 duration=0.000289089 average_per_call=1.44545e-06"
2020/09/16,17:32:32.432,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=5 duration=5.5e-06 average_per_call=1.1e-06"
2020/09/16,17:32:42.464,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/16,17:32:42.464,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=206 duration=3.66847 average_per_call=0.0178081"
2020/09/16,17:32:42.464,opengl_Wrapper.cpp:107,ERROR, "glDrawArraysUnbuffered: call_count=26514 duration=0.576189 average_per_call=2.17315e-05"
2020/09/16,17:32:42.464,opengl_Wrapper.cpp:107,ERROR, "glDrawElementsUnbuffered: call_count=7619 duration=0.273894 average_per_call=3.59488e-05"
2020/09/16,17:32:42.464,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=88172 duration=0.0589254 average_per_call=6.683e-07"
2020/09/16,17:32:42.464,opengl_Wrapper.cpp:107,ERROR, "glDeleteProgram: call_count=39 duration=0.0455784 average_per_call=0.00116868"
2020/09/16,17:32:42.464,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_Quit: call_count=1 duration=0.0334388 average_per_call=0.0334388"
2020/09/16,17:32:42.464,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=88172 duration=0.0268129 average_per_call=3.04098e-07"
2020/09/16,17:32:42.464,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=412 duration=0.0177092 average_per_call=4.29835e-05"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=17523 duration=0.00906921 average_per_call=5.1756e-07"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=31 duration=0.00775653 average_per_call=0.000250211"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=2492 duration=0.00640613 average_per_call=2.57068e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=2657 duration=0.00421779 average_per_call=1.58743e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=1033 duration=0.00413707 average_per_call=4.00491e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glDeleteTextures: call_count=559 duration=0.00289214 average_per_call=5.17377e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=2251 duration=0.00202683 average_per_call=9.00412e-07"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=94 duration=0.00202197 average_per_call=2.15104e-05"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=2251 duration=0.00173281 average_per_call=7.69797e-07"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=855 duration=0.00154798 average_per_call=1.81051e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=760 duration=0.00141802 average_per_call=1.86581e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=1159 duration=0.00108483 average_per_call=9.36006e-07"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=1159 duration=0.000995422 average_per_call=8.58863e-07"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=413 duration=0.000716504 average_per_call=1.73488e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=166 duration=0.00058039 average_per_call=3.49633e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=320 duration=0.000538659 average_per_call=1.68331e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=322 duration=0.000401857 average_per_call=1.248e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=31 duration=0.000154054 average_per_call=4.96948e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glDeleteShader: call_count=4 duration=0.000146904 average_per_call=3.6726e-05"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glDeleteFramebuffers: call_count=6 duration=3.4721e-05 average_per_call=5.78683e-06"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glPixelStorei: call_count=42 duration=3.2722e-05 average_per_call=7.79095e-07"
2020/09/16,17:32:42.465,opengl_Wrapper.cpp:107,ERROR, "glDeleteBuffers: call_count=1 duration=1.0407e-05 average_per_call=1.0407e-05"

fzurita commented 4 years ago

Well, I see an optimization target for GLideN64. Reduce glDraw calls and reduce glBind calls. I can't think of a good way to do this without doing some kind of batch pre-processing before giving stuff to the driver.

fzurita commented 4 years ago

By the way, what kind of performance improvement do you get with threading on with the RPi4?

dankcushions commented 4 years ago

After that glDrawArraysUnbuffered and glDrawElementsUnbuffered seem to be the next big hitters. I'm not sure what could be done to optimize that, but the high number of calls to those two seem to be troublesome. GL_EXT_buffer_storage extension would help in that case.

According to MESA, this extension should be supported by v3d (pi MESA driver), however I'm not quite sure how to read this list.. Does GL extension support mean it's available in a GLES 3.x context?

fzurita commented 4 years ago

Not necessarily, it would depend if the GLES driver implemented it.

dankcushions commented 4 years ago

Looking at this thread: https://www.raspberrypi.org/forums/viewtopic.php?f=63&t=249636

it looks like it's available now. I'm on Mesa 19.3.2.

I could create some debug code to see if GLideN64 was finding it correctly, or was there something in the logs that proves it wasn't working?

fzurita commented 4 years ago

You could put some logging here:

https://github.com/gonetz/GLideN64/blob/master/src/Graphics/OpenGLContext/opengl_GLInfo.cpp#L103

That's where the plugin makes the determination.

Edit: There is a secondary check here too:

https://github.com/gonetz/GLideN64/blob/master/src/Graphics/OpenGLContext/opengl_ContextImpl.cpp#L70

dankcushions commented 4 years ago

Thanks! It passes the first check (the extension is present) but it won't pass the second check as Pi 4 is (currently) GLES 3.1, not 3.2. What's the purpose of the version check, if the buffered storage extension is supported?

fzurita commented 4 years ago

I can't remember. It may have been performance issues, I wish there was a comment there. You could always try taking it out and see what happens.

loganmc10 commented 4 years ago

I think it might be because the buffered drawer depends on glDrawRangeElementsBaseVertex, which didn't become standard until GLES 3.2. However I think there is a GLES 3.1 extension (GL_EXT_draw_elements_base_vertex) that would allow it to work

dankcushions commented 4 years ago

@loganmc10 I believe that extension is present: see here (note that's an old list, as current MESA driver has GLES 3.1.

also, skipping the version check gets me this (doesn't seem to be obviously faster):

2020/09/17,10:34:43.127,opengl_Utils.cpp:60,WARNING, "Could not query EGL extensions on this device"
2020/09/17,10:34:43.127,opengl_Utils.cpp:60,WARNING, "Could not query EGL extensions on this device"
2020/09/17,10:34:52.482,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/17,10:34:52.482,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=298 duration=1.92362 average_per_call=0.00645511"
2020/09/17,10:34:52.482,opengl_Wrapper.cpp:107,ERROR, "glLinkProgram: call_count=39 duration=0.799188 average_per_call=0.020492"
2020/09/17,10:34:52.482,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_Init: call_count=1 duration=0.609199 average_per_call=0.609199"
2020/09/17,10:34:52.482,opengl_Wrapper.cpp:107,ERROR, "glDrawArrays: call_count=35253 duration=0.57356 average_per_call=1.62698e-05"
2020/09/17,10:34:52.482,opengl_Wrapper.cpp:107,ERROR, "glCompileShader: call_count=52 duration=0.304456 average_per_call=0.00585492"
2020/09/17,10:34:52.482,opengl_Wrapper.cpp:107,ERROR, "glDrawRangeElementsBaseVertex: call_count=822 duration=0.0983144 average_per_call=0.000119604"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=319 duration=0.0946194 average_per_call=0.000296612"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=105037 duration=0.0671075 average_per_call=6.38894e-07"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=109 duration=0.0384314 average_per_call=0.000352582"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=486 duration=0.0339103 average_per_call=6.97744e-05"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glBufferStorage: call_count=3 duration=0.0337578 average_per_call=0.0112526"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_SetVideoMode: call_count=1 duration=0.0335619 average_per_call=0.0335619"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=49046 duration=0.0308333 average_per_call=6.2866e-07"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=105037 duration=0.0275406 average_per_call=2.62199e-07"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=1534 duration=0.00607432 average_per_call=3.95979e-06"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=1162 duration=0.00468567 average_per_call=4.03242e-06"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glGetUniformLocation: call_count=1700 duration=0.00379863 average_per_call=2.23449e-06"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glBufferData: call_count=1 duration=0.00203203 average_per_call=0.00203203"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=1462 duration=0.00178938 average_per_call=1.22393e-06"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=803 duration=0.00153823 average_per_call=1.91561e-06"
2020
/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=1460 duration=0.00153668 average_per_call=1.05252e-06"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glGetStringi: call_count=764 duration=0.000861369 average_per_call=1.12745e-06"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=109 duration=0.000786374 average_per_call=7.21444e-06"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glShaderSource: call_count=52 duration=0.000698005 average_per_call=1.34232e-05"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=283 duration=0.000611206 average_per_call=2.15974e-06"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glBindVertexArray: call_count=277 duration=0.000588764 average_per_call=2.1255e-06"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=277 duration=0.00055361 average_per_call=1.99859e-06"
2020/09/17,10:34:52.483,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=436 duration=0.000486791 average_per_call=1.11649e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glCreateProgram: call_count=39 duration=0.000458618 average_per_call=1.17594e-05"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=295 duration=0.000435771 average_per_call=1.47719e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=434 duration=0.000395064 average_per_call=9.10286e-07"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glCreateShader: call_count=52 duration=0.000340416 average_per_call=6.54646e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=289 duration=0.000338169 average_per_call=1.17013e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glBindAttribLocation: call_count=154 duration=0.000305466 average_per_call=1.98355e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glGetProgramiv: call_count=39 duration=0.00022153 average_per_call=5.68026e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glGetShaderiv: call_count=70 duration=0.000206405 average_per_call=2.94864e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glAttachShader: call_count=78 duration=0.000184088 average_per_call=2.3601e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=59 duration=0.000162626 average_per_call=2.75637e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glMapBufferRange: call_count=3 duration=0.000122256 average_per_call=4.0752e-05"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glDeleteShader: call_count=48 duration=0.000121365 average_per_call=2.52844e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glFramebufferTexture2D: call_count=12 duration=0.000118442 average_per_call=9.87017e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glDeleteTextures: call_count=6 duration=5.8389e-05 average_per_call=9.7315e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glUniform1f: call_count=39 duration=3.8724e-05 average_per_call=9.92923e-07"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glUniform2i: call_count=55 duration=3.8068e-05 average_per_call=6.92145e-07"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glGenFramebuffers: call_count=11 duration=3.7722e-05 average_per_call=3.42927e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glGetIntegerv: call_count=17 duration=2.9055e-05 average_per_call=1.70912e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glDeleteFramebuffers: call_count=5 duration=2.6259e-05 average_per_call=5.2518e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glGetString: call_count=3 duration=2.2019e-05 average_per_call=7.33967e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glPolygonOffset: call_count=1 duration=2.0296e-05 average_per_call=2.0296e-05"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glBindBuffer: call_count=5 duration=1.9963e-05 average_per_call=3.9926e-06"
2020/09/17,10:34:52.484,opengl_Wrapper.cpp:107,ERROR, "glVertexAttribPointer: call_count=7 duration=1.9701e-05 average_per_call=2.81443e-06"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "glGenVertexArrays: call_count=2 duration=1.7888e-05 average_per_call=8.944e-06"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "glDebugMessageCallback: call_count=1 duration=1.5629e-05 average_per_call=1.5629e-05"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "glGenBuffers: call_count=4 duration=1.3259e-05 average_per_call=3.31475e-06"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SetAttribute: call_count=7 duration=6.703e-06 average_per_call=9.57571e-07"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "glGetError: call_count=4 duration=6.371e-06 average_per_call=1.59275e-06"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=1 duration=3.667e-06 average_per_call=3.667e-06"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "glDebugMessageControl: call_count=1 duration=3.407e-06 average_per_call=3.407e-06"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "glGetFloatv: call_count=1 duration=3.185e-06 average_per_call=3.185e-06"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "glPixelStorei: call_count=2 duration=2.259e-06 average_per_call=1.1295e-06"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "glDepthMask: call_count=1 duration=1.889e-06 average_per_call=1.889e-06"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "glCullFace: call_count=1 duration=1.814e-06 average_per_call=1.814e-06"
2020/09/17,10:34:52.485,opengl_Wrapper.cpp:107,ERROR, "glDepthFunc: call_count=1 duration=1.093e-06 average_per_call=1.093e-06"
2020/09/17,10:35:02.487,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=595 duration=7.00357 average_per_call=0.0117707"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glDrawArrays: call_count=14775 duration=0.35291 average_per_call=2.38856e-05"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glDrawRangeElementsBaseVertex: call_count=47722 duration=0.212824 average_per_call=4.45966e-06"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=1190 duration=0.0585429 average_per_call=4.91957e-05"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=65913 duration=0.0461066 average_per_call=6.99508e-07"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=65913 duration=0.0192317 average_per_call=2.91773e-07"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=4192 duration=0.0151758 average_per_call=3.62018e-06"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=2976 duration=0.0127335 average_per_call=4.27873e-06"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=18523 duration=0.0119771 average_per_call=6.46606e-07"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=2363 duration=0.00444519 average_per_call=1.88116e-06"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=3605 duration=0.00356218 average_per_call=9.88121e-07"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=3606 duration=0.0030587 average_per_call=8.48225e-07"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glBindVertexArray: call_count=1173 duration=0.00301942 average_per_call=2.5741e-06"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=1190 duration=0.00229261 average_per_call=1.92656e-06"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=1190 duration=0.00184571 average_per_call=1.55102e-06"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=1188 duration=0.00163712 average_per_call=1.37804e-06"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1190 duration=0.00130569 average_per_call=1.09722e-06"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=113 duration=0.000286474 average_per_call=2.53517e-06"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=7 duration=0.000194033 average_per_call=2.7719e-05"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=7 duration=0.000184126 average_per_call=2.63037e-05"
2020/09/17,10:35:02.488,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=7 duration=0.0001007 average_per_call=1.43857e-05"
2020/09/17,10:35:02.489,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=35 duration=3.53e-05 average_per_call=1.00857e-06"
2020/09/17,10:35:02.489,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=8 duration=8.833e-06 average_per_call=1.10412e-06"
2020/09/17,10:35:02.489,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=1 duration=3.556e-06 average_per_call=3.556e-06"
2020/09/17,10:35:12.492,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/17,10:35:12.492,opengl_Wrapper.cpp:107,ERROR, "glDrawArrays: call_count=25427 duration=0.625261 average_per_call=2.45904e-05"
2020/09/17,10:35:12.492,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=572 duration=0.500301 average_per_call=0.000874652"
2020/09/17,10:35:12.492,opengl_Wrapper.cpp:107,ERROR, "glDrawRangeElementsBaseVertex: call_count=8214 duration=0.0721704 average_per_call=8.78627e-06"
2020/09/17,10:35:12.492,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=75750 duration=0.056112 average_per_call=7.40753e-07"
2020/09/17,10:35:12.492,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=1144 duration=0.0528304 average_per_call=4.61804e-05"
2020/09/17,10:35:12.492,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=299 duration=0.0313242 average_per_call=0.000104763"
2020/09/17,10:35:12.492,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=20379 duration=0.02634 average_per_call=1.29251e-06"
2020/09/17,10:35:12.492,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=75750 duration=0.0205033 average_per_call=2.70671e-07"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=3358 duration=0.0122365 average_per_call=3.64398e-06"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=2858 duration=0.0117376 average_per_call=4.10693e-06"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=299 duration=0.0102011 average_per_call=3.41174e-05"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=2122 duration=0.0039255 average_per_call=1.84991e-06"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=3185 duration=0.00324244 average_per_call=1.01804e-06"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=3186 duration=0.00296791 average_per_call=9.31549e-07"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=1521 duration=0.0027763 average_per_call=1.82531e-06"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glBindVertexArray: call_count=979 duration=0.0025898 average_per_call=2.64536e-06"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=1142 duration=0.00228394 average_per_call=1.99995e-06"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=1142 duration=0.0018036 average_per_call=1.57934e-06"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1533 duration=0.00150259 average_per_call=9.80162e-07"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=1144 duration=0.00137575 average_per_call=1.20257e-06"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=299 duration=0.00111156 average_per_call=3.71758e-06"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=1495 duration=0.00104376 average_per_call=6.98168e-07"
2020/09/17,10:35:12.493,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=4 duration=5.036e-06 average_per_call=1.259e-06"
2020/09/17,10:35:22.507,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/17,10:35:22.507,opengl_Wrapper.cpp:107,ERROR, "glDrawArrays: call_count=121012 duration=2.65149 average_per_call=2.19109e-05"
2020/09/17,10:35:22.507,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=426 duration=1.66586 average_per_call=0.00391048"
2020/09/17,10:35:22.507,opengl_Wrapper.cpp:107,ERROR, "glDrawRangeElementsBaseVertex: call_count=43708 duration=0.678594 average_per_call=1.55256e-05"
2020/09/17,10:35:22.507,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=419980 duration=0.283948 average_per_call=6.76098e-07"
2020/09/17,10:35:22.507,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=101299 duration=0.123623 average_per_call=1.22038e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=419980 duration=0.108011 average_per_call=2.57182e-07"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=852 duration=0.0564651 average_per_call=6.62736e-05"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=62683 duration=0.0329082 average_per_call=5.24993e-07"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=119 duration=0.0173761 average_per_call=0.000146017"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=3629 duration=0.0144196 average_per_call=3.97344e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=2130 duration=0.0102353 average_per_call=4.8053e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=123 duration=0.00608814 average_per_call=4.9497e-05"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=1596 duration=0.00372546 average_per_call=2.33425e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=3275 duration=0.00349566 average_per_call=1.06738e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=3275 duration=0.00343032 average_per_call=1.04742e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=685 duration=0.00260945 average_per_call=3.80941e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glBindVertexArray: call_count=744 duration=0.00179923 average_per_call=2.41832e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=1130 duration=0.00167229 average_per_call=1.4799e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=852 duration=0.00163821 average_per_call=1.92279e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=1632 duration=0.00135478 average_per_call=8.30137e-07"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=1130 duration=0.0012387 average_per_call=1.0962e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=119 duration=0.000863985 average_per_call=7.26038e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=595 duration=0.000596334 average_per_call=1.00224e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=14 duration=1.5206e-05 average_per_call=1.08614e-06"
2020/09/17,10:35:22.508,opengl_Wrapper.cpp:107,ERROR, "glPixelStorei: call_count=12 duration=1.3516e-05 average_per_call=1.12633e-06"
2020/09/17,10:35:32.508,opengl_Wrapper.cpp:101,ERROR, "Profiling output"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "CoreVideo_GL_SwapBuffers: call_count=308 duration=1.50342 average_per_call=0.00488123"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glDrawArrays: call_count=10068 duration=0.533829 average_per_call=5.30224e-05"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glDrawRangeElementsBaseVertex: call_count=11618 duration=0.374642 average_per_call=3.22467e-05"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glClearBufferfv: call_count=616 duration=0.0316142 average_per_call=5.13217e-05"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glBindTexture: call_count=35417 duration=0.0269677 average_per_call=7.61435e-07"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glTexStorage2D: call_count=58 duration=0.0111765 average_per_call=0.000192698"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glActiveTexture: call_count=35417 duration=0.0103335 average_per_call=2.91766e-07"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glUniform2f: call_count=12751 duration=0.00794573 average_per_call=6.23146e-07"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glUseProgram: call_count=2459 duration=0.00773022 average_per_call=3.14365e-06"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glBindFramebuffer: call_count=1897 duration=0.00725492 average_per_call=3.82442e-06"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glTexSubImage2D: call_count=120 duration=0.00349136 average_per_call=2.90947e-05"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glCheckFramebufferStatus: call_count=531 duration=0.00228758 average_per_call=4.30805e-06"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glUniform1i: call_count=725 duration=0.00225438 average_per_call=3.10949e-06"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glViewport: call_count=1205 duration=0.00218706 average_per_call=1.81498e-06"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glEnable: call_count=2282 duration=0.0020403 average_per_call=8.94085e-07"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glDisable: call_count=2280 duration=0.0019139 average_per_call=8.39429e-07"
2020/09/17,10:35:32.509,opengl_Wrapper.cpp:107,ERROR, "glUniform4fv: call_count=935 duration=0.00191309 average_per_call=2.04609e-06"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glBindVertexArray: call_count=588 duration=0.00136351 average_per_call=2.31889e-06"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glScissor: call_count=618 duration=0.00122888 average_per_call=1.98848e-06"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glDisableVertexAttribArray: call_count=986 duration=0.00116467 average_per_call=1.1812e-06"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glFramebufferTexture2D: call_count=329 duration=0.001005 average_per_call=3.0547e-06"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glEnableVertexAttribArray: call_count=986 duration=0.00088957 average_per_call=9.02201e-07"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glGenTextures: call_count=58 duration=0.000510674 average_per_call=8.80472e-06"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glTexParameteri: call_count=325 duration=0.000340019 average_per_call=1.04621e-06"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glDepthMask: call_count=184 duration=0.0002607 average_per_call=1.41685e-06"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glDepthFunc: call_count=184 duration=0.000224972 average_per_call=1.22267e-06"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glBlendFunc: call_count=43 duration=0.000158537 average_per_call=3.68691e-06"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glClear: call_count=1 duration=6.9757e-05 average_per_call=6.9757e-05"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glPixelStorei: call_count=48 duration=4.2738e-05 average_per_call=8.90375e-07"
2020/09/17,10:35:32.510,opengl_Wrapper.cpp:107,ERROR, "glGenFramebuffers: call_count=2 duration=1.1371e-05 average_per_call=5.6855e-06"

dankcushions commented 4 years ago

Sorry, realised the above log was still vysnc off, which seems to have it's own quirks. Edited the previous post with a log with vysnc on, so it's comparable. Does anyone have a tool to parse these profiling logs so I can see if there's an improvement? It does seem like it might be a little bit faster, but still obviously suffering with these scenes.

fzurita commented 4 years ago

You could probably use Excel or the libre office equivalent to parse them.

fzurita commented 4 years ago

Also, you don't happen to have "Render 2d elements at N64 resolution" enabled right? That would cause big slow downs in 2D scenes.

dankcushions commented 4 years ago

had already loaded them in Excel it's just a hassle splitting up the data in the final string. I assumed it was some kind of common profiling format that had a tool to parse. I guess I'll set up some macros to work with it.

Also, you don't happen to have "Render 2d elements at N64 resolution" enabled right? That would cause big slow downs in 2D scenes.

No:

# Render 2D texrects in native resolution to fix misalignment between parts of 2D image. (0=Off, 1=Optimized, 2=Unoptimized)
EnableNativeResTexrects = 0

Langerz82 commented 4 years ago

In https://github.com/gonetz/GLideN64/blob/master/src/Graphics/OpenGLContext/opengl_UnbufferedDrawer.cpp#L98

Could we replace the current code with:

        glMemoryBarrier(GL_SHADER_IMAGE_ACCESS_BARRIER_BIT);
        glDrawArrays(GLenum(_params.mode), 0, GLint(_params.verticesCount));

        /*for (GLint i = 0; i < GLint(_params.verticesCount); i += 3) {
            glMemoryBarrier(GL_SHADER_IMAGE_ACCESS_BARRIER_BIT);
            glDrawArrays(GLenum(_params.mode), i, 3);
        }*/

Theoretically this should reduce DrawArrays calls, but I'm not sure if it breaks anything.

fzurita commented 4 years ago

That code is not normally reached unless specific settings are enabled.

fzurita commented 3 years ago

Ok, I think I tracked down the commits that caused the loss in performance in 2D heavy scenes. These two commits are causing upwards of a 50% performance loss in the golden eye menus:

a405ad86596d4ec33d84c67400212af3dd3ac236 4834359ec1ad031210fb6ade6c9d50e953b20d0e

These are two back-to-back commits, the first one crashes, the 2nd one doesn't crash but has a bad performance regression.

@standard-two-simplex Any idea why these two commits are causing such a bad performance regression?

fzurita commented 3 years ago

Introduced by this pull request: https://github.com/gonetz/GLideN64/pull/2202

ghost commented 3 years ago

Any idea why these two commits are causing such a bad performance regression?

I can only guess. These changes perform clamp mask and mirror operations twice, then perform four texel fetches using those coordinates. I have read somewhere that old GPUs or bad drivers performing texture lookups on dinamically calculated indices can be slow. textureEngine0() calls clampWrapMirror() and the output is used to fetch the texel, so perhaps this is the case.

If you want to narrow down the issue try modifying the following functions of the fragment shader (located in combinerProgramBuilder.cpp`) for dummy ones:

textureEngine0() and textureEngine1()
TEX_NEAREST() and TEX_FILTER() macros where texelFetch is used or the texelFetch() in readTexCopy() .

For example, in the case of textureEngine0() you can redefine it as

"highp vec2[5] textureEngine0(in highp vec2 texCoord) \n"
"{  \n"
"  highp vec2[5] tcData; \n" // {tc00, tc01, tc10, tc11, frPart}
"  tcData[0] = 0.0; \n"
"  tcData[3] = 0.0; \n"
"  tcData[1] = 0.0; \n"
"  tcData[2] = 0.0; \n"
"  tcData[4] = 0.0; \n"
"  return tcData;"
"}  \n"

The final output will be wrong but you will be able to check if the performance issue is gone.

fzurita commented 3 years ago

Well, TEX_NEAREST() and TEX_FILTER() have no visible impact in performance.

Stubbing out textureEngine0/1 restores performance to almost old levels with obvious graphical glitches. Even with that commented out, performance is still about 10% slower than what it used to be.

fzurita commented 3 years ago

To me, it seems like we are just hitting the limits of mobile GPUs with all the shader operations we are performing after that pull request.

I can't find a single culprit that is making everything slower, it seems like it's all slower when you add up all the new stuff.

I guess ideally, it would be nice to have a legacy texture coordinate calculation for devices with slower GPUs.

gonetz commented 3 years ago

I guess ideally, it would be nice to have a legacy texture coordinate calculation for devices with slower GPUs.

This legacy code becomes a heavy burden. I have an alternative proposal: remove all legacy code, including GLES 2.0 support after the next public release. Slow mobile GPUs may use 4.0 version.

Precise emulation of N64 hardware requires to move more and more stuff in shaders and often use inefficient calculations.

Jj0YzL5nvJ commented 3 years ago

The issue is that GLideN64 is putting too much faith in version numbers that not everyone respects. #2381

fzurita commented 3 years ago

Well, that's only part of the problem. Fixing that will only yield a relatively slow increase in performance. Also, the mobile devices I'm testing on already meets the requirements for those extensions.

fzurita commented 3 years ago

@gonetz That's probably not a bad idea. Although, personally, I don't want to maintain two versions of the same plugins in the Android app. I will probably end up dropping GLES 2.0 support once that happens. This slow down though is happening on devices with GLES 3.2.

dankcushions commented 3 years ago

yes, in this case pi4 is GLES 3.1, but has several additional extensions it seems. i'm not suggesting we optimize for GLES 2.0 devices.

perhaps long term a vulkan port is the best solution, as that is becoming the norm in mobile GPUs and desktop GPUs alike, but that's another story.

To me, it seems like we are just hitting the limits of mobile GPUs with all the shader operations we are performing after that pull request. I can't find a single culprit that is making everything slower, it seems like it's all slower when you add up all the new stuff.

maybe running some of these fragments through the GLSL optimizer could help? I tried to isolate textureEngine0 and try it through that but I was getting syntax errors - perhaps I needed some init from earlier (I don't really know what I'm doing!)

fzurita commented 3 years ago

Most modern GPU drivers have decent optimizers built in. The additional pass of optimization probably won't help much in most cases. I'm not saying it's not worth trying though if someone wants to do it.

fzurita commented 3 years ago

I found one thing that really helps performance in Golden eye 2D areas. Setting resolution to 640x480 and disable native resolution factor. For some reason, native resolution factor of 2X or more really kills performance in the golden eye menus.

gonetz commented 3 years ago

This slow down though is happening on devices with GLES 3.2.

:(

ghost commented 3 years ago

For some reason, native resolution factor of 2X or more really kills performance in the golden eye menus.

This is normal behaviour when fragment processing is the bottleneck. 2x resolution means each primitive has 4x as many pixels, so fragment processing becomes 4x slower. Similarly, 8x resolution would be 64x slower. Even powerful GPUs will struggle at a high enough resolution.

However, I don't know the reason why Goldeneye should be more expensive than other games in the same resolution.

Stubbing out textureEngine0/1 restores performance to almost old levels with obvious graphical glitches. Even with that commented out, performance is still about 10% slower than what it used to be.

I'll try to check if any of those computations is expensive in my laptop.

gonetz / GLideN64

Severe slowdown during certain 2D scenes on Raspberry Pi 4 (GLES 3.1) #2329