Add OpenGL debug logging

- use '-v GPU' to enable
- driver messages (errors, warnings etc) are logged
- debug marker messages are inserted into the API call stream by
MythOpenGLPainter, OpenGLVideo and VideoOutputOpenGL at key points.
- these debug markers assist in the analysis of trace calls and on some
GLES implementations will mark the start and end of actual frames as
there are no swapBuffers type calls for apitrace to seperate frames.
- example usage:

// log driver messages
mythfrontend -v gpu

// analyse API calls, profiling etc
apitrace trace  -o mythfrontend.trace mythfrontend -v gpu
qapitrace mythfrontend.trace

mythtv/libs/libmythtv/openglvideo.cpp

@@ -726,6 +726,9 @@ void OpenGLVideo::UpdateInputFrame(const VideoFrame *frame)
 {
     OpenGLLocker ctx_lock(gl_context);
 
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        gl_context->logDebugMarker(LOC + "UPDATE_FRAME_START");
+
     if (frame->width  != video_dim.width()  ||
         frame->height != video_dim.height() ||
         frame->width  < 1 || frame->height < 1 ||
@@ -773,6 +776,9 @@ void OpenGLVideo::UpdateInputFrame(const VideoFrame *frame)
     }
 
     gl_context->UpdateTexture(inputTextures[0], buf);
+
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        gl_context->logDebugMarker(LOC + "UPDATE_FRAME_END");
 }
 
 void OpenGLVideo::SetDeinterlacing(bool deinterlacing)
@@ -816,6 +822,9 @@ void OpenGLVideo::PrepareFrame(bool topfieldfirst, FrameScanType scan,
 
     OpenGLLocker ctx_lock(gl_context);
 
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        gl_context->logDebugMarker(LOC + "PREP_FRAME_START");
+
     vector<GLuint> inputs = inputTextures;
     QSize inputsize = inputTextureSize;
     QSize realsize  = gl_context->GetTextureSize(video_disp_dim);
@@ -826,6 +835,9 @@ void OpenGLVideo::PrepareFrame(bool topfieldfirst, FrameScanType scan,
         OpenGLFilterType type = it->first;
         OpenGLFilter *filter = it->second;
 
+        if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+            gl_context->logDebugMarker(LOC + QString("FILTER_START_%1").arg(FilterToString(type)));
+
         // texture coordinates
         float width = video_disp_dim.width();
         if (kGLUYVY == videoType)
@@ -971,6 +983,8 @@ void OpenGLVideo::PrepareFrame(bool topfieldfirst, FrameScanType scan,
             inputs.push_back(fb->texture());
         inputsize = realsize;
     }
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        gl_context->logDebugMarker(LOC + "PREP_FRAME_END");
 }
 
 void OpenGLVideo::RotateTextures(void)
@@ -1014,7 +1028,7 @@ OpenGLVideo::OpenGLFilterType OpenGLVideo::StringToFilter(const QString &filter)
 {
     OpenGLFilterType ret = kGLFilterNone;
 
-    if (filter.contains("master"))
+    if (filter.contains("yuv2rgb"))
         ret = kGLFilterYUV2RGB;
     else if (filter.contains("resize"))
         ret = kGLFilterResize;
@@ -1033,7 +1047,7 @@ QString OpenGLVideo::FilterToString(OpenGLFilterType filt)
         case kGLFilterNone:
             break;
         case kGLFilterYUV2RGB:
-            return "master";
+            return "yuv2rgb";
         case kGLFilterResize:
             return "resize";
         case kGLFilterBicubic:

mythtv/libs/libmythtv/videoout_opengl.cpp

@@ -491,6 +491,9 @@ void VideoOutputOpenGL::ProcessFrame(VideoFrame *frame, OSD */*osd*/,
     bool deint_proc = m_deinterlacing && (m_deintFilter != nullptr);
     OpenGLLocker ctx_lock(gl_context);
 
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        gl_context->logDebugMarker(LOC + "PROCESS_FRAME_START");
+
     bool pauseframe = false;
     if (!frame)
     {
@@ -522,6 +525,9 @@ void VideoOutputOpenGL::ProcessFrame(VideoFrame *frame, OSD */*osd*/,
 
     if (gl_videochain && sw_frame && !dummy)
         gl_videochain->UpdateInputFrame(frame);
+
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        gl_context->logDebugMarker(LOC + "PROCESS_FRAME_END");
 }
 
 void VideoOutputOpenGL::PrepareFrame(VideoFrame *buffer, FrameScanType t,
@@ -532,6 +538,9 @@ void VideoOutputOpenGL::PrepareFrame(VideoFrame *buffer, FrameScanType t,
 
     OpenGLLocker ctx_lock(gl_context);
 
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        gl_context->logDebugMarker(LOC + "PREPARE_FRAME_START");
+
     if (!buffer)
     {
         buffer = vbuffers.GetScratchFrame();
@@ -658,6 +667,9 @@ void VideoOutputOpenGL::PrepareFrame(VideoFrame *buffer, FrameScanType t,
 
     if (vbuffers.GetScratchFrame() == buffer)
         vbuffers.SetLastShownFrameToScratch();
+
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        gl_context->logDebugMarker(LOC + "PREPARE_FRAME_END");
 }
 
 void VideoOutputOpenGL::Show(FrameScanType /*scan*/)
@@ -669,6 +681,8 @@ void VideoOutputOpenGL::Show(FrameScanType /*scan*/)
         return;
     }
 
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        gl_context->logDebugMarker(LOC + "SHOW");
     if (gl_context)
         gl_context->swapBuffers();
 }

mythtv/libs/libmythui/mythpainter_ogl.cpp

@@ -94,6 +94,9 @@ void MythOpenGLPainter::Begin(QPaintDevice *parent)
         }
     }
 
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        realRender->logDebugMarker("PAINTER_FRAME_START");
+
     DeleteTextures();
     realRender->makeCurrent();
 
@@ -114,13 +117,13 @@ void MythOpenGLPainter::End(void)
         LOG(VB_GENERAL, LOG_ERR, "FATAL ERROR: No render device in 'End'");
         return;
     }
-    else
-    {
-        realRender->Flush(false);
-        if (target == nullptr && swapControl)
-            realRender->swapBuffers();
-        realRender->doneCurrent();
-    }
+
+    realRender->Flush(false);
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        realRender->logDebugMarker("PAINTER_FRAME_END");
+    if (target == nullptr && swapControl)
+        realRender->swapBuffers();
+    realRender->doneCurrent();
 
     MythPainter::End();
 }

mythtv/libs/libmythui/mythrender_opengl.cpp

@@ -89,6 +89,10 @@ MythRenderOpenGL* MythRenderOpenGL::Create(const QString&, QPaintDevice* device)
 #endif
     if (qApp->platformName().contains("egl"))
         format.setRenderableType(QSurfaceFormat::OpenGLES);
+
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+        format.setOption(QSurfaceFormat::DebugContext);
+
     return new MythRenderOpenGL(format, device);
 }
 
@@ -97,7 +101,8 @@ MythRenderOpenGL::MythRenderOpenGL(const QSurfaceFormat& format, QPaintDevice* d
   : QOpenGLContext(),
     QOpenGLFunctions(),
     MythRender(type),
-    m_lock(QMutex::Recursive)
+    m_lock(QMutex::Recursive),
+    m_openglDebugger(nullptr)
 {
     QWidget *w = dynamic_cast<QWidget*>(device);
     m_window = (w) ? w->windowHandle() : nullptr;
@@ -112,9 +117,28 @@ MythRenderOpenGL::~MythRenderOpenGL()
         return;
     makeCurrent();
     DeleteOpenGLResources();
+    if (m_openglDebugger)
+        delete m_openglDebugger;
     doneCurrent();
 }
 
+void MythRenderOpenGL::messageLogged(const QOpenGLDebugMessage &Message)
+{
+    // filter out our own messages
+    if (Message.source() != QOpenGLDebugMessage::ApplicationSource)
+        LOG(VB_GPU, LOG_INFO, LOC + Message.message());
+}
+
+void MythRenderOpenGL::logDebugMarker(const QString &Message)
+{
+    if (m_openglDebugger)
+    {
+        QOpenGLDebugMessage message = QOpenGLDebugMessage::createApplicationMessage(
+            Message, 0, QOpenGLDebugMessage::NotificationSeverity, QOpenGLDebugMessage::MarkerType);
+        m_openglDebugger->logMessage(message);
+    }
+}
+
 bool MythRenderOpenGL::Init(void)
 {
     if (!isValid())
@@ -127,6 +151,29 @@ bool MythRenderOpenGL::Init(void)
     initializeOpenGLFunctions();
     m_features = openGLFeatures();
 
+    // don't enable this by default - it can generate a lot of detail
+    if (VERBOSE_LEVEL_CHECK(VB_GPU, LOG_INFO))
+    {
+        m_openglDebugger = new QOpenGLDebugLogger();
+        if (m_openglDebugger->initialize())
+        {
+            connect(m_openglDebugger, SIGNAL(messageLogged(QOpenGLDebugMessage)), this, SLOT(messageLogged(QOpenGLDebugMessage)));
+            QOpenGLDebugLogger::LoggingMode mode = QOpenGLDebugLogger::AsynchronousLogging;
+#if 0
+            // this will impact performance but can be very useful
+            mode = QOpenGLDebugLogger::SynchronousLogging;
+#endif
+            m_openglDebugger->startLogging(mode);
+            LOG(VB_GENERAL, LOG_INFO, LOC + "GPU debug logging started");
+        }
+        else
+        {
+            LOG(VB_GENERAL, LOG_WARNING, LOC + "Failed to initialise OpenGL logging");
+            delete m_openglDebugger;
+            m_openglDebugger = nullptr;
+        }
+    }
+
     InitProcs();
     Init2DState();
 

mythtv/libs/libmythui/mythrender_opengl.h

@@ -11,6 +11,7 @@
 #include <QOpenGLFunctions>
 #include <QOpenGLShaderProgram>
 #include <QOpenGLFramebufferObject>
+#include <QOpenGLDebugLogger>
 #include <QHash>
 #include <QMutex>
 #include <QMatrix4x4>
@@ -175,6 +176,10 @@ class MUI_PUBLIC MythRenderOpenGL : public QOpenGLContext, protected QOpenGLFunc
                        int alpha);
     bool RectanglesAreAccelerated(void) { return true; }
 
+  public slots:
+    void messageLogged  (const QOpenGLDebugMessage &Message);
+    void logDebugMarker (const QString &Message);
+
   protected:
     ~MythRenderOpenGL();
     void DrawBitmapPriv(uint tex, const QRect *src, const QRect *dst,
@@ -287,6 +292,7 @@ class MUI_PUBLIC MythRenderOpenGL : public QOpenGLContext, protected QOpenGLFunc
 
   private:
     void DebugFeatures (void);
+    QOpenGLDebugLogger *m_openglDebugger;
     QWindow *m_window;
 };