Merge pull request #14772 from lrusak/opengl-debugging

OpenGL(ES) debugging improvements

8 files changed, 307 insertions, 33 deletions

diff --git a/xbmc/guilib/Shader.cpp b/xbmc/guilib/Shader.cpp
index fc8095e75a..7cf820e52e 100644
--- a/xbmc/guilib/Shader.cpp
+++ b/xbmc/guilib/Shader.cpp
@@ -11,6 +11,7 @@
 #include "filesystem/File.h"
 #include "utils/log.h"
 #include "utils/GLUtils.h"
+#include "utils/StringUtils.h"
 #include "rendering/RenderSystem.h"
 
 #ifdef HAS_GLES
@@ -51,6 +52,9 @@ bool CShader::LoadSource(const std::string& filename, const std::string& prefix)
       pos = versionPos + 1;
   }
   m_source.insert(pos, prefix);
+
+  m_filenames = filename;
+
   return true;
 }
 
@@ -72,6 +76,9 @@ bool CShader::AppendSource(const std::string& filename)
   }
   getline(file, temp, '\0');
   m_source.append(temp);
+
+  m_filenames.append(" " + filename);
+
   return true;
 }
 
@@ -102,9 +109,27 @@ bool CShader::InsertSource(const std::string& filename, const std::string& loc)
 
   m_source.insert(locPos, temp);
 
+  m_filenames.append(" " + filename);
+
   return true;
 }
 
+std::string CShader::GetSourceWithLineNumbers() const
+{
+  int i{1};
+  auto lines = StringUtils::Split(m_source, "\n");
+  for (auto& line : lines)
+  {
+    line.insert(0, StringUtils::Format("%3d: ", i));
+    i++;
+  }
+
+  auto output = StringUtils::Join(lines, "\n");
+
+  return output;
+}
+
+
 //////////////////////////////////////////////////////////////////////
 // CGLSLVertexShader
 //////////////////////////////////////////////////////////////////////
@@ -254,7 +279,8 @@ bool CGLSLShaderProgram::CompileAndLink()
   // compiled vertex shader
   if (!m_pVP->Compile())
   {
-    CLog::Log(LOGERROR, "GL: Error compiling vertex shader");
+    CLog::Log(LOGERROR, "GL: Error compiling vertex shader: {}", m_pVP->GetName());
+    CLog::Log(LOGDEBUG, "GL: vertex shader source:\n{}", m_pVP->GetSourceWithLineNumbers());
     return false;
   }
 
@@ -262,7 +288,8 @@ bool CGLSLShaderProgram::CompileAndLink()
   if (!m_pFP->Compile())
   {
     m_pVP->Free();
-    CLog::Log(LOGERROR, "GL: Error compiling fragment shader");
+    CLog::Log(LOGERROR, "GL: Error compiling fragment shader: {}", m_pFP->GetName());
+    CLog::Log(LOGDEBUG, "GL: fragment shader source:\n{}", m_pFP->GetSourceWithLineNumbers());
     return false;
   }
 
diff --git a/xbmc/guilib/Shader.h b/xbmc/guilib/Shader.h
index d689b1b239..a0228cd175 100644
--- a/xbmc/guilib/Shader.h
+++ b/xbmc/guilib/Shader.h
@@ -32,11 +32,17 @@ namespace Shaders {
     virtual bool InsertSource(const std::string& filename, const std::string& loc);
     bool OK() const { return m_compiled; }
 
+    std::string GetName() const { return m_filenames; }
+    std::string GetSourceWithLineNumbers() const;
+
   protected:
     std::string m_source;
     std::string m_lastLog;
     std::vector<std::string> m_attr;
     bool m_compiled = false;
+
+  private:
+    std::string m_filenames;
   };
 
 
diff --git a/xbmc/rendering/gles/RenderSystemGLES.cpp b/xbmc/rendering/gles/RenderSystemGLES.cpp
index 1c41943232..60eecd2d59 100644
--- a/xbmc/rendering/gles/RenderSystemGLES.cpp
+++ b/xbmc/rendering/gles/RenderSystemGLES.cpp
@@ -9,10 +9,11 @@
 #include "guilib/DirtyRegion.h"
 #include "windowing/GraphicContext.h"
 #include "settings/AdvancedSettings.h"
+#include "settings/SettingsComponent.h"
 #include "RenderSystemGLES.h"
 #include "rendering/MatrixGL.h"
-#include "utils/log.h"
 #include "utils/GLUtils.h"
+#include "utils/log.h"
 #include "utils/TimeUtils.h"
 #include "utils/SystemInfo.h"
 #include "utils/MathUtils.h"
@@ -20,6 +21,10 @@
 #include "XTimeUtils.h"
 #endif
 
+#if defined(TARGET_LINUX)
+#include "utils/EGLUtils.h"
+#endif
+
 CRenderSystemGLES::CRenderSystemGLES()
  : CRenderSystemBase()
 {
@@ -71,6 +76,30 @@ bool CRenderSystemGLES::InitRenderSystem()
 
   m_RenderExtensions += " ";
 
+//! @todo remove TARGET_RASPBERRY_PI when Raspberry Pi updates their GL headers
+#if defined(GL_KHR_debug) && defined(TARGET_LINUX) && !defined(TARGET_RASPBERRY_PI)
+  if (CServiceBroker::GetSettingsComponent()->GetAdvancedSettings()->m_openGlDebugging)
+  {
+    if (IsExtSupported("GL_KHR_debug"))
+    {
+      auto glDebugMessageCallback = CEGLUtils::GetRequiredProcAddress<PFNGLDEBUGMESSAGECALLBACKKHRPROC>("glDebugMessageCallbackKHR");
+      auto glDebugMessageControl = CEGLUtils::GetRequiredProcAddress<PFNGLDEBUGMESSAGECONTROLKHRPROC>("glDebugMessageControlKHR");
+
+      glEnable(GL_DEBUG_OUTPUT_SYNCHRONOUS_KHR);
+      glDebugMessageCallback(KODI::UTILS::GL::GlErrorCallback, nullptr);
+
+      // ignore shader compilation information
+      glDebugMessageControl(GL_DEBUG_SOURCE_SHADER_COMPILER_KHR, GL_DEBUG_TYPE_OTHER_KHR, GL_DONT_CARE, 0, nullptr, GL_FALSE);
+
+      CLog::Log(LOGDEBUG, "OpenGL(ES): debugging enabled");
+    }
+    else
+    {
+      CLog::Log(LOGDEBUG, "OpenGL(ES): debugging requested but the required extension isn't available (GL_KHR_debug)");
+    }
+  }
+#endif
+
   LogGraphicsInfo();
 
   m_bRenderCreated = true;
diff --git a/xbmc/settings/AdvancedSettings.cpp b/xbmc/settings/AdvancedSettings.cpp
index e0e46b1bf8..f6ba324537 100644
--- a/xbmc/settings/AdvancedSettings.cpp
+++ b/xbmc/settings/AdvancedSettings.cpp
@@ -434,6 +434,8 @@ void CAdvancedSettings::Initialize()
   m_extraLogEnabled = false;
   m_extraLogLevels = 0;
 
+  m_openGlDebugging = false;
+
   m_userAgent = g_sysinfo.GetUserAgent();
 
   m_initialized = true;
@@ -1231,6 +1233,8 @@ void CAdvancedSettings::ParseSettingsFile(const std::string &file)
       m_seekSteps.push_back(atoi((*it).c_str()));
   }
 
+  XMLUtils::GetBoolean(pRootElement, "opengldebugging", m_openGlDebugging);
+
   // load in the settings overrides
   CServiceBroker::GetSettingsComponent()->GetSettings()->LoadHidden(pRootElement);
 }
diff --git a/xbmc/settings/AdvancedSettings.h b/xbmc/settings/AdvancedSettings.h
index 6e024e919e..1f6d5e06b0 100644
--- a/xbmc/settings/AdvancedSettings.h
+++ b/xbmc/settings/AdvancedSettings.h
@@ -382,6 +382,8 @@ class CAdvancedSettings : public ISettingCallback, public ISettingsHandler
     False to show at the bottom of video (default) */
     bool m_videoAssFixedWorks;
 
+    bool m_openGlDebugging;
+
     std::string m_userAgent;
 
   private:
diff --git a/xbmc/utils/EGLUtils.cpp b/xbmc/utils/EGLUtils.cpp
index 27a0567f96..25d93985a6 100644
--- a/xbmc/utils/EGLUtils.cpp
+++ b/xbmc/utils/EGLUtils.cpp
@@ -17,6 +17,8 @@
 
 #include <EGL/eglext.h>
 
+#include <map>
+
 namespace
 {
 //! @todo remove when Raspberry Pi updates their EGL headers
@@ -34,7 +36,7 @@ namespace
 #endif
 
 #define X(VAL) std::make_pair(VAL, #VAL)
-std::array<std::pair<EGLint, const char*>, 32> eglAttributes =
+std::map<EGLint, const char*> eglAttributes =
 {
   // please keep attributes in accordance to:
   // https://www.khronos.org/registry/EGL/sdk/docs/man/html/eglGetConfigAttrib.xhtml
@@ -71,8 +73,64 @@ std::array<std::pair<EGLint, const char*>, 32> eglAttributes =
   X(EGL_TRANSPARENT_GREEN_VALUE),
   X(EGL_TRANSPARENT_BLUE_VALUE)
 };
+
+std::map<EGLenum, const char*> eglErrors =
+{
+  // please keep errors in accordance to:
+  // https://www.khronos.org/registry/EGL/sdk/docs/man/html/eglGetError.xhtml
+  X(EGL_SUCCESS),
+  X(EGL_NOT_INITIALIZED),
+  X(EGL_BAD_ACCESS),
+  X(EGL_BAD_ALLOC),
+  X(EGL_BAD_ATTRIBUTE),
+  X(EGL_BAD_CONFIG),
+  X(EGL_BAD_CONTEXT),
+  X(EGL_BAD_CURRENT_SURFACE),
+  X(EGL_BAD_DISPLAY),
+  X(EGL_BAD_MATCH),
+  X(EGL_BAD_NATIVE_PIXMAP),
+  X(EGL_BAD_NATIVE_WINDOW),
+  X(EGL_BAD_PARAMETER),
+  X(EGL_BAD_SURFACE),
+  X(EGL_CONTEXT_LOST),
+};
+
+std::map<EGLint, const char*> eglErrorType =
+{
+//! @todo remove when Raspberry Pi updates their EGL headers
+#if !defined(TARGET_RASPBERRY_PI)
+  X(EGL_DEBUG_MSG_CRITICAL_KHR),
+  X(EGL_DEBUG_MSG_ERROR_KHR),
+  X(EGL_DEBUG_MSG_WARN_KHR),
+  X(EGL_DEBUG_MSG_INFO_KHR),
+#endif
+};
 #undef X
+
+} // namespace
+
+//! @todo remove when Raspberry Pi updates their EGL headers
+#if !defined(TARGET_RASPBERRY_PI)
+void EglErrorCallback(EGLenum error, const char *command, EGLint messageType, EGLLabelKHR threadLabel, EGLLabelKHR objectLabel, const char* message)
+{
+  std::string errorStr;
+  std::string typeStr;
+
+  auto eglError = eglErrors.find(error);
+  if (eglError != eglErrors.end())
+  {
+    errorStr = eglError->second;
+  }
+
+  auto eglType = eglErrorType.find(messageType);
+  if (eglType != eglErrorType.end())
+  {
+    typeStr = eglType->second;
+  }
+
+  CLog::Log(LOGDEBUG, "EGL Debugging:\nError: {}\nCommand: {}\nType: {}\nMessage: {}", errorStr, command, typeStr, message);
 }
+#endif
 
 std::set<std::string> CEGLUtils::GetClientExtensions()
 {
@@ -112,7 +170,16 @@ bool CEGLUtils::HasClientExtension(const std::string& name)
 
 void CEGLUtils::LogError(const std::string& what)
 {
-  CLog::Log(LOGERROR, "%s (EGL error %d)", what.c_str(), eglGetError());
+  EGLenum error = eglGetError();
+  std::string errorStr = StringUtils::Format("0x%04X", error);
+
+  auto eglError = eglErrors.find(error);
+  if (eglError != eglErrors.end())
+  {
+    errorStr = eglError->second;
+  }
+
+  CLog::Log(LOGERROR, "{} ({})", what.c_str(), errorStr);
 }
 
 CEGLContextUtils::CEGLContextUtils()
@@ -122,6 +189,22 @@ CEGLContextUtils::CEGLContextUtils()
 CEGLContextUtils::CEGLContextUtils(EGLenum platform, std::string const& platformExtension)
 : m_platform{platform}
 {
+//! @todo remove when Raspberry Pi updates their EGL headers
+#if !defined(TARGET_RASPBERRY_PI)
+  if (CEGLUtils::HasClientExtension("EGL_KHR_debug"))
+  {
+    auto eglDebugMessageControl = CEGLUtils::GetRequiredProcAddress<PFNEGLDEBUGMESSAGECONTROLKHRPROC>("eglDebugMessageControlKHR");
+
+    EGLAttrib eglDebugAttribs[] = {EGL_DEBUG_MSG_CRITICAL_KHR, EGL_TRUE,
+                                   EGL_DEBUG_MSG_ERROR_KHR, EGL_TRUE,
+                                   EGL_DEBUG_MSG_WARN_KHR, EGL_TRUE,
+                                   EGL_DEBUG_MSG_INFO_KHR, EGL_TRUE,
+                                   EGL_NONE};
+
+    eglDebugMessageControl(EglErrorCallback, eglDebugAttribs);
+  }
+#endif
+
   m_platformSupported = CEGLUtils::HasClientExtension("EGL_EXT_platform_base") && CEGLUtils::HasClientExtension(platformExtension);
 }
 
@@ -321,6 +404,15 @@ bool CEGLContextUtils::CreateContext(CEGLAttributesVec contextAttribs)
   if (CEGLUtils::HasExtension(m_eglDisplay, "EGL_IMG_context_priority"))
     contextAttribs.Add({{EGL_CONTEXT_PRIORITY_LEVEL_IMG, EGL_CONTEXT_PRIORITY_HIGH_IMG}});
 
+//! @todo remove when Raspberry Pi updates their EGL headers
+#if !defined(TARGET_RASPBERRY_PI)
+  if (CEGLUtils::HasExtension(m_eglDisplay, "EGL_KHR_create_context") &&
+      CServiceBroker::GetSettingsComponent()->GetAdvancedSettings()->m_openGlDebugging)
+  {
+    contextAttribs.Add({{EGL_CONTEXT_FLAGS_KHR, EGL_CONTEXT_OPENGL_DEBUG_BIT_KHR}});
+  }
+#endif
+
   m_eglContext = eglCreateContext(m_eglDisplay, eglConfig,
                                   EGL_NO_CONTEXT, contextAttribs.Get());
 
diff --git a/xbmc/utils/GLUtils.cpp b/xbmc/utils/GLUtils.cpp
index e7376c0396..e381fd6bc9 100644
--- a/xbmc/utils/GLUtils.cpp
+++ b/xbmc/utils/GLUtils.cpp
@@ -7,47 +7,148 @@
  */
 
 #include "GLUtils.h"
+
 #include "log.h"
 #include "ServiceBroker.h"
 #include "settings/AdvancedSettings.h"
 #include "settings/SettingsComponent.h"
+#include "rendering/MatrixGL.h"
 #include "rendering/RenderSystem.h"
+#include "utils/StringUtils.h"
+
+#include <map>
+#include <utility>
+
+namespace
+{
+
+#define X(VAL) std::make_pair(VAL, #VAL)
+std::map<GLenum, const char*> glErrors =
+{
+  // please keep attributes in accordance to:
+  // https://www.khronos.org/registry/OpenGL-Refpages/gl4/html/glGetError.xhtml
+  X(GL_NO_ERROR),
+  X(GL_INVALID_ENUM),
+  X(GL_INVALID_VALUE),
+  X(GL_INVALID_OPERATION),
+  X(GL_INVALID_FRAMEBUFFER_OPERATION),
+  X(GL_OUT_OF_MEMORY),
+#if defined(HAS_GL)
+  X(GL_STACK_UNDERFLOW),
+  X(GL_STACK_OVERFLOW),
+#endif
+};
+
+std::map<GLenum, const char*> glErrorSource =
+{
+//! @todo remove TARGET_RASPBERRY_PI when Raspberry Pi updates their GL headers
+#if defined(HAS_GLES) && defined(TARGET_LINUX) && !defined(TARGET_RASPBERRY_PI)
+  X(GL_DEBUG_SOURCE_API_KHR),
+  X(GL_DEBUG_SOURCE_WINDOW_SYSTEM_KHR),
+  X(GL_DEBUG_SOURCE_SHADER_COMPILER_KHR),
+  X(GL_DEBUG_SOURCE_THIRD_PARTY_KHR),
+  X(GL_DEBUG_SOURCE_APPLICATION_KHR),
+  X(GL_DEBUG_SOURCE_OTHER_KHR),
+#endif
+};
+
+std::map<GLenum, const char*> glErrorType =
+{
+//! @todo remove TARGET_RASPBERRY_PI when Raspberry Pi updates their GL headers
+#if defined(HAS_GLES) && defined(TARGET_LINUX) && !defined(TARGET_RASPBERRY_PI)
+  X(GL_DEBUG_TYPE_ERROR_KHR),
+  X(GL_DEBUG_TYPE_DEPRECATED_BEHAVIOR_KHR),
+  X(GL_DEBUG_TYPE_UNDEFINED_BEHAVIOR_KHR),
+  X(GL_DEBUG_TYPE_PORTABILITY_KHR),
+  X(GL_DEBUG_TYPE_PERFORMANCE_KHR),
+  X(GL_DEBUG_TYPE_OTHER_KHR),
+  X(GL_DEBUG_TYPE_MARKER_KHR),
+#endif
+};
+
+std::map<GLenum, const char*> glErrorSeverity =
+{
+//! @todo remove TARGET_RASPBERRY_PI when Raspberry Pi updates their GL headers
+#if defined(HAS_GLES) && defined(TARGET_LINUX) && !defined(TARGET_RASPBERRY_PI)
+  X(GL_DEBUG_SEVERITY_HIGH_KHR),
+  X(GL_DEBUG_SEVERITY_MEDIUM_KHR),
+  X(GL_DEBUG_SEVERITY_LOW_KHR),
+  X(GL_DEBUG_SEVERITY_NOTIFICATION_KHR),
+#endif
+};
+#undef X
+
+} // namespace
 
-void _VerifyGLState(const char* szfile, const char* szfunction, int lineno){
-#if defined(HAS_GL) && defined(_DEBUG)
-#define printMatrix(matrix)                                             \
-  {                                                                     \
-    for (int ixx = 0 ; ixx<4 ; ixx++)                                   \
-      {                                                                 \
-        CLog::Log(LOGDEBUG, "% 3.3f % 3.3f % 3.3f % 3.3f ",             \
-                  matrix[ixx*4], matrix[ixx*4+1], matrix[ixx*4+2],      \
-                  matrix[ixx*4+3]);                                     \
-      }                                                                 \
+void KODI::UTILS::GL::GlErrorCallback(GLenum source, GLenum type, GLuint id, GLenum severity, GLsizei length, const GLchar* message, const void* userParam)
+{
+  std::string sourceStr;
+  std::string typeStr;
+  std::string severityStr;
+
+  auto glSource = glErrorSource.find(source);
+  if (glSource != glErrorSource.end())
+  {
+    sourceStr = glSource->second;
   }
-  if (CServiceBroker::GetSettingsComponent()->GetAdvancedSettings()->m_logLevel < LOG_LEVEL_DEBUG_FREEMEM)
-    return;
+
+  auto glType = glErrorType.find(type);
+  if (glType != glErrorType.end())
+  {
+    typeStr = glType->second;
+  }
+
+  auto glSeverity = glErrorSeverity.find(severity);
+  if (glSeverity != glErrorSeverity.end())
+  {
+    severityStr = glSeverity->second;
+  }
+
+  CLog::Log(LOGDEBUG, "OpenGL(ES) Debugging:\nSource: {}\nType: {}\nSeverity: {}\nID: {}\nMessage: {}", sourceStr, typeStr, severityStr, id, message);
+}
+
+static void PrintMatrix(const GLfloat* matrix, std::string matrixName)
+{
+  CLog::Log(LOGDEBUG, "{}:\n{:> 10.3f} {:> 10.3f} {:> 10.3f} {:> 10.3f}\n{:> 10.3f} {:> 10.3f} {:> 10.3f} {:> 10.3f}\n{:> 10.3f} {:> 10.3f} {:> 10.3f} {:> 10.3f}\n{:> 10.3f} {:> 10.3f} {:> 10.3f} {:> 10.3f}",
+                      matrixName,
+                      matrix[0], matrix[1], matrix[2], matrix[3],
+                      matrix[4], matrix[5], matrix[6], matrix[7],
+                      matrix[8], matrix[9], matrix[10], matrix[11],
+                      matrix[12], matrix[13], matrix[14], matrix[15]);
+}
+
+void _VerifyGLState(const char* szfile, const char* szfunction, int lineno)
+{
   GLenum err = glGetError();
-  if (err==GL_NO_ERROR)
+  if (err == GL_NO_ERROR)
+  {
     return;
-  CLog::Log(LOGERROR, "GL ERROR: %s\n", gluErrorString(err));
+  }
+
+  auto error = glErrors.find(err);
+  if (error != glErrors.end())
+  {
+    CLog::Log(LOGERROR, "GL(ES) ERROR: {}", error->second);
+  }
+
   if (szfile && szfunction)
-      CLog::Log(LOGERROR, "In file:%s function:%s line:%d", szfile, szfunction, lineno);
-  GLboolean bools[16];
+  {
+    CLog::Log(LOGERROR, "In file: {} function: {} line: {}", szfile, szfunction, lineno);
+  }
+
+  GLboolean scissors;
+  glGetBooleanv(GL_SCISSOR_TEST, &scissors);
+  CLog::Log(LOGDEBUG, "Scissor test enabled: {}", scissors == GL_TRUE ? "True" : "False");
+
   GLfloat matrix[16];
   glGetFloatv(GL_SCISSOR_BOX, matrix);
-  CLog::Log(LOGDEBUG, "Scissor box: %f, %f, %f, %f", matrix[0], matrix[1], matrix[2], matrix[3]);
-  glGetBooleanv(GL_SCISSOR_TEST, bools);
-  CLog::Log(LOGDEBUG, "Scissor test enabled: %d", (int)bools[0]);
+  CLog::Log(LOGDEBUG, "Scissor box: {}, {}, {}, {}", matrix[0], matrix[1], matrix[2], matrix[3]);
+
   glGetFloatv(GL_VIEWPORT, matrix);
-  CLog::Log(LOGDEBUG, "Viewport: %f, %f, %f, %f", matrix[0], matrix[1], matrix[2], matrix[3]);
-  glGetFloatv(GL_PROJECTION_MATRIX, matrix);
-  CLog::Log(LOGDEBUG, "Projection Matrix:");
-  printMatrix(matrix);
-  glGetFloatv(GL_MODELVIEW_MATRIX, matrix);
-  CLog::Log(LOGDEBUG, "Modelview Matrix:");
-  printMatrix(matrix);
-//  abort();
-#endif
+  CLog::Log(LOGDEBUG, "Viewport: {}, {}, {}, {}", matrix[0], matrix[1], matrix[2], matrix[3]);
+
+  PrintMatrix(glMatrixProject.Get(), "Projection Matrix");
+  PrintMatrix(glMatrixModview.Get(), "Modelview Matrix");
 }
 
 void LogGraphicsInfo()
diff --git a/xbmc/utils/GLUtils.h b/xbmc/utils/GLUtils.h
index afacfe8e05..2dea0673b0 100644
--- a/xbmc/utils/GLUtils.h
+++ b/xbmc/utils/GLUtils.h
@@ -21,6 +21,19 @@
 
 #include "system_gl.h"
 
+namespace KODI
+{
+namespace UTILS
+{
+namespace GL
+{
+
+void GlErrorCallback(GLenum source, GLenum type, GLuint id, GLenum severity, GLsizei length, const GLchar* message, const void* userParam);
+
+}
+}
+}
+
 void _VerifyGLState(const char* szfile, const char* szfunction, int lineno);
 #if defined(GL_DEBUGGING) && (defined(HAS_GL) || defined(HAS_GLES))
 #define VerifyGLState() _VerifyGLState(__FILE__, __FUNCTION__, __LINE__)