Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

QtWebEngine: Error from previous GL command #199

Closed
JHagemeister opened this issue Apr 21, 2022 · 12 comments
Closed

QtWebEngine: Error from previous GL command #199

JHagemeister opened this issue Apr 21, 2022 · 12 comments

Comments

@JHagemeister
Copy link

JHagemeister commented Apr 21, 2022

I am running into the following issue when closing my Qt application (Qt version 5.15):

[20380:20418:0421/161153.973944:ERROR:gles2_cmd_decoder.cc(2843)] [.RenderCompositor-0x7fd88000bd90]GL ERROR :GL_INVALID_OPERATION : BackFramebuffer::Destroy: <- error from previous GL command

I can reproduce this issue with a very tiny example code snippet run wrapped with "vglrun -d egl".

#include <QApplication>
#include <QMainWindow>
#include <QWebEngineView>

int main(int argc, char *argv[])
{
    QApplication a(argc, argv);

    QMainWindow w;
    new QWebEngineView(&w);
    w.show();

    return a.exec();
}
@JHagemeister
Copy link
Author

JHagemeister commented Apr 25, 2022

Another slightly different example based on Qt's example https://doc.qt.io/qt-5/qtwebengine-webenginewidgets-minimal-example.html:

#include <QApplication>
#include <QUrl>
#include <QWebEngineView>

int main(int argc, char *argv[])
{
    QApplication app(argc, argv);

    QWebEngineView view;
    view.setUrl(QUrl(QStringLiteral("https://www.qt.io")));
    view.show();

    return app.exec();
}

With the above example, I get the error message "[.BrowserMainThread-0x1ac7310]GL ERROR :GL_INVALID_OPERATION : BackFramebuffer::Destroy: <- error from previous GL command" once in a while on shut-down.

@tsondergaard
Copy link

Further investigation shows that we can get the same error on launch (not shutdown) with the first example posted by @JHagemeister when using vglrun -d egl, but it does not reproduce when using vglrun -d $DISPLAY. In other words the error seems to be related to using the EGL backend.

If there is anything else we can provide that would be helpful please let us know. Also, we will happily take suggestions for debugging/tracing tools we can use to investigate further.

@JHagemeister
Copy link
Author

I followed the OpenGL debugging guidelines provided in https://www.khronos.org/opengl/wiki/Debug_Output
and added something along the lines of

void GLAPIENTRY
MessageCallback( GLenum source,
                 GLenum type,
                 GLuint id,
                 GLenum severity,
                 GLsizei length,
                 const GLchar* message,
                 const void* userParam )
{
  fprintf( stderr, "GL CALLBACK: %s type = 0x%x, severity = 0x%x, message = %s\n",
           ( type == GL_DEBUG_TYPE_ERROR ? "** GL ERROR **" : "" ),
            type, severity, message );
}

// During init, enable debug output
glEnable              ( GL_DEBUG_OUTPUT );
glDebugMessageCallback( MessageCallback, 0 );

to VirtualGL. I then obtained the following information:

GL CALLBACK: ** GL ERROR ** type = 0x824c, severity = 0x9146, message = GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound.

@dcommander
Copy link
Member

I am looking into it.

@dcommander
Copy link
Member

Unfortunately the issue is so intermittent on my system that it is impossible to debug. I have only observed it once in over 100 invocations. Please find a more reliable way to reproduce it.

@JHagemeister
Copy link
Author

JHagemeister commented May 5, 2022

Does the following help maybe? Also, I run into this stacktrace everytime I run the first example program posted above.
(Running with 9168122 plus tiny logging addition)

#0 backend::MessageCallback (source=33350, type=33356, id=1282, severity=37190, length=92,
message=0x7fffd3514d20 "GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound.", userParam=0x0) at /home/jh/src/virtualgl/server/backend.cpp:796
#1 0x00007fffd20e0b3d in ?? () from /lib64/libnvidia-eglcore.so.470.103.01
#2 0x00007fffd20e0d11 in ?? () from /lib64/libnvidia-eglcore.so.470.103.01
#3 0x00007fffd20e0ee9 in ?? () from /lib64/libnvidia-eglcore.so.470.103.01
#4 0x00007fffd20f1a1b in ?? () from /lib64/libnvidia-eglcore.so.470.103.01
#5 0x00007ffff78f7922 in _glBindFramebuffer (framebuffer=2, target=36009) at /home/jh/src/virtualgl/server/faker-sym.h:561
#6 backend::BufferState::~BufferState (this=0x7f1d70, __in_chrg=) at /home/jh/src/virtualgl/server/BufferState.h:68
#7 0x00007ffff795e625 in backend::FakePbuffer::createBuffer (this=0x7c8300, useRBOContext=false, ignoreReadDrawBufs=true) at /home/jh/src/virtualgl/server/FakePbuffer.cpp:167
#8 0x00007ffff78f1fd9 in backend::makeCurrent (dpy=0x41a130, draw=2, read=2, ctx=0x7f1411) at /home/jh/src/virtualgl/server/backend.cpp:827
#9 0x00007ffff791c2ba in glXMakeContextCurrent (dpy=0x41a130, draw=2, read=2, ctx=0x7f1411) at /home/jh/src/virtualgl/server/faker-glx.cpp:1886
#10 0x00007fffdb999f58 in QGLXContext::makeCurrent (this=this@entry=0x7f1970, surface=0x7c7a60) at qglxintegration.cpp:583
#11 0x00007fffee7a979c in QOpenGLContext::makeCurrent (this=this@entry=0x7fffffffd540, surface=surface@entry=0x7c7370) at kernel/qopenglcontext.cpp:992
#12 0x00007fffdb99a2a7 in QGLXContext::queryDummyContext () at qglxintegration.cpp:725
#13 0x00007fffdb99aba9 in QGLXContext::supportsThreading () at qglxintegration.cpp:805
#14 0x00007ffff031df85 in QtWebEngineCore::WebEngineContext::isGpuServiceOnUIThread ()
at /home/ts/src/easyviz/third-party/rpmsource/easyviz-qt/rpmbuild/BUILD/qt-everywhere-src-5.15.2/qtwebengine/src/core/web_engine_context.cpp:508
#15 0x00007ffff0321e61 in QtWebEngineCore::WebEngineContext::registerMainThreadFactories ()
at /home/ts/src/easyviz/third-party/rpmsource/easyviz-qt/rpmbuild/BUILD/qt-everywhere-src-5.15.2/qtwebengine/src/core/web_engine_context_threads.cpp:132
#16 0x00007ffff0320427 in QtWebEngineCore::WebEngineContext::WebEngineContext (this=0x8a74d0)
at /home/ts/src/easyviz/third-party/rpmsource/easyviz-qt/rpmbuild/BUILD/qt-everywhere-src-5.15.2/qtwebengine/src/core/web_engine_context.cpp:757
#17 0x00007ffff0321864 in QtWebEngineCore::WebEngineContext::current ()
at /home/ts/src/easyviz/third-party/rpmsource/easyviz-qt/rpmbuild/BUILD/qt-everywhere-src-5.15.2/qtwebengine/src/core/web_engine_context.cpp:433
#18 0x00007ffff7fd1bc7 in QSharedPointerQtWebEngineCore::WebContentsAdapter::create<>() () at /opt/rh/devtoolset-9/root/usr/include/c++/9/new:174
#19 QWebEnginePagePrivate::QWebEnginePagePrivate (this=0x8a75b0, _profile=0x0) at api/qwebenginepage.cpp:146
#20 0x00007ffff7fd2954 in QWebEnginePage::QWebEnginePage (this=0x8a6d80, parent=) at api/qwebenginepage.cpp:779
#21 0x00007ffff7fe1c23 in QWebEngineView::page (this=this@entry=0x7e8050) at api/qwebengineview.cpp:190
#22 0x00007ffff7fe262a in QWebEngineView::showEvent (this=0x7e8050, event=) at api/qwebengineview.cpp:392
#23 0x00007fffeee8f346 in QWidget::event (this=this@entry=0x7e8050, event=event@entry=0x7fffffffdb10) at kernel/qwidget.cpp:8663
#24 0x00007ffff7fe24be in QWebEngineView::event (this=0x7e8050, ev=0x7fffffffdb10) at api/qwebengineview.cpp:372
#25 0x00007fffeee4d7c2 in QApplicationPrivate::notify_helper (this=this@entry=0x40d7c0, receiver=receiver@entry=0x7e8050, e=e@entry=0x7fffffffdb10) at kernel/qapplication.cpp:3632
#26 0x00007fffeee560e2 in QApplication::notify (this=0x7fffffffdd80, receiver=0x7e8050, e=0x7fffffffdb10) at kernel/qapplication.cpp:3156
#27 0x00007fffedd15a91 in QCoreApplication::notifyInternal2 (receiver=0x7e8050, event=0x7fffffffdb10) at ../../include/QtCore/5.15.2/QtCore/private/../../../../../src/corelib/thread/qthread_p.h:325
#28 0x00007fffeee8bdda in QWidgetPrivate::show_helper (this=this@entry=0x7fe860) at kernel/qwidget.cpp:7813
#29 0x00007fffeee8ee45 in QWidgetPrivate::setVisible (this=0x7fe860, visible=) at kernel/qwidget.cpp:8111
#30 0x00007fffeee8bd29 in QWidgetPrivate::showChildren (this=this@entry=0x7feb70, spontaneous=spontaneous@entry=false) at kernel/qwidget.cpp:8183
#31 0x00007fffeee8bdb4 in QWidgetPrivate::show_helper (this=this@entry=0x7feb70) at kernel/qwidget.cpp:7768
#32 0x00007fffeee8ee45 in QWidgetPrivate::setVisible (this=0x7feb70, visible=) at kernel/qwidget.cpp:8111
#33 0x0000000000401235 in main (argc=1, argv=0x7fffffffde98) at ../gl-test/main.cc:11

@JHagemeister
Copy link
Author

JHagemeister commented May 5, 2022

This is how I added further OpenGL error logging:

From d4750065bea6a4d0de04cd648c0f199c884009c5 Mon Sep 17 00:00:00 2001
From: Julian Hagemeister
Date: Thu, 5 May 2022 20:30:34 +0200
Subject: [PATCH] Nobug: Add additional error logging to VirtualGL

---
 server/backend.cpp     | 18 ++++++++++++++++++
 server/faker-gl.cpp    |  9 +++++++++
 server/faker-mapfile.c |  2 ++
 server/faker-sym.h     | 12 ++++++++++++
 4 files changed, 41 insertions(+)

diff --git a/server/backend.cpp b/server/backend.cpp
index 9f13ec2..3e02ffc 100644
--- a/server/backend.cpp
+++ b/server/backend.cpp
@@ -782,6 +782,19 @@ Bool isDirect(GLXContext ctx)
 		return _glXIsDirect(DPY3D, ctx);
 }
 
+void GLAPIENTRY
+MessageCallback( GLenum source,
+                 GLenum type,
+                 GLuint id,
+                 GLenum severity,
+                 GLsizei length,
+                 const GLchar* message,
+                 const void* userParam )
+{
+  fprintf( stderr, "GL CALLBACK: %s type = 0x%x, severity = 0x%x, message = %s\n",
+           ( type == GL_DEBUG_TYPE_ERROR ? "** GL ERROR **" : "" ),
+            type, severity, message );
+}
 
 Bool makeCurrent(Display *dpy, GLXDrawable draw, GLXDrawable read,
 	GLXContext ctx)
@@ -796,6 +809,11 @@ Bool makeCurrent(Display *dpy, GLXDrawable draw, GLXDrawable read,
 			EGLBoolean ret = (Bool)_eglMakeCurrent(EDPY, EGL_NO_SURFACE,
 				EGL_NO_SURFACE, (EGLContext)ctx);
 			if(!ret) THROW_EGL("eglMakeCurrent()");
+
+            glEnable(GL_DEBUG_OUTPUT);
+            glEnable(GL_DEBUG_OUTPUT_SYNCHRONOUS);
+            glDebugMessageCallback(MessageCallback, 0);
+
 			setCurrentDrawableEGL(draw);
 			setCurrentReadDrawableEGL(read);
 			if(!ctx) return True;
diff --git a/server/faker-gl.cpp b/server/faker-gl.cpp
index d2888cd..d2af786 100644
--- a/server/faker-gl.cpp
+++ b/server/faker-gl.cpp
@@ -802,6 +802,15 @@ void glReadBuffer(GLenum mode)
 	CATCH();
 }
 
+void glEnable(GLenum cap)
+{
+    _glEnable(cap);
+}
+
+void glDebugMessageCallback(DEBUGPROC callback, const void * userParam)
+{
+    _glDebugMessageCallback(callback, userParam);
+}
 
 void glReadPixels(GLint x, GLint y, GLsizei width, GLsizei height,
 	GLenum format, GLenum type, GLvoid *pixels)
diff --git a/server/faker-mapfile.c b/server/faker-mapfile.c
index 707ba4b..3a096d1 100644
--- a/server/faker-mapfile.c
+++ b/server/faker-mapfile.c
@@ -120,6 +120,8 @@
 		glReadBuffer;
 		glReadPixels;
 		glViewport;
+        glEnable;
+        glDebugMessageCallback;
 
 		/* OpenCL */
 		#ifdef FAKEOPENCL
diff --git a/server/faker-sym.h b/server/faker-sym.h
index 0fa1e5c..e38b97d 100644
--- a/server/faker-sym.h
+++ b/server/faker-sym.h
@@ -628,6 +628,18 @@ VFUNCDEF7(glReadPixels, GLint, x, GLint, y, GLsizei, width, GLsizei, height,
 VFUNCDEF4(glViewport, GLint, x, GLint, y, GLsizei, width, GLsizei, height,
 	glViewport)
 
+VFUNCDEF1(glEnable, GLenum, cap, glEnable)
+
+typedef void (APIENTRY *DEBUGPROC)(GLenum source,
+            GLenum type,
+            GLuint id,
+            GLenum severity,
+            GLsizei length,
+            const GLchar *message,
+            const void *userParam);
+
+VFUNCDEF2(glDebugMessageCallback, DEBUGPROC, callback, const void *, userParam,
+          glDebugMessageCallback)
 
 #ifdef FAKEOPENCL
 
-- 
1.8.3.1

@dcommander
Copy link
Member

@JHagemeister I need to be able to reliably reproduce the issue in order to diagnose it, but on my machine, the issue is so unreliable that I won't necessarily encounter it even if I run the test application in a loop for hundreds of iterations. That is impossible to work with. If you can more reliably reproduce the issue, then I would suggest adding a print statement to ~BufferState() to determine the value of oldDrawFBO and oldReadFBO. The error seems to occur when we try to re-bind the FBO that was bound when FakePbuffer::createBuffer() was called. My best guess is that something is killing that FBO in the background, but I have no idea what.

@JHagemeister
Copy link
Author

Thank you for your reply and I of course understand that you need a reliable way to reproduce in order to trouble shoot.

Please let me briefly recap my oservations before I answer your questions:

Initially, without any particular debugging enabled, I encountered (with some frequency)"[20380:20418:0421/161153.973944:ERROR:gles2_cmd_decoder.cc(2843)] [.RenderCompositor-0x7fd88000bd90]GL ERROR :GL_INVALID_OPERATION : BackFramebuffer::Destroy: <- error from previous GL command"
source file: qtwebengine/src/3rdparty/chromium/gpu/command_buffer/service/gles2_cmd_decoder.cc

I then enhanced OpenGL error logging in VirtualGL as posted in the diff above along the lines of
glEnable(GL_DEBUG_OUTPUT);
glEnable(GL_DEBUG_OUTPUT_SYNCHRONOUS);
glDebugMessageCallback(MessageCallback, 0);
in order to try to find out what exactly those OpenGL errors are.

I then obtained the following:

GL CALLBACK: ** GL ERROR ** type = 0x824c, severity = 0x9146, message = GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound.
GL CALLBACK: ** GL ERROR ** type = 0x824c, severity = 0x9146, message = GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound.
GL CALLBACK: ** GL ERROR ** type = 0x824c, severity = 0x9146, message = GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound.
GL CALLBACK: ** GL ERROR ** type = 0x824c, severity = 0x9146, message = GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound.
GL CALLBACK:  type = 0x8251, severity = 0x826b, message = Buffer detailed info: Buffer object 5 (bound to GL_ARRAY_BUFFER_ARB, usage hint is GL_STATIC_DRAW) will use VIDEO memory as the source for buffer object operations.
GL CALLBACK:  type = 0x8251, severity = 0x826b, message = Buffer detailed info: Buffer object 6 (bound to GL_ELEMENT_ARRAY_BUFFER_ARB, usage hint is GL_STATIC_DRAW) will use VIDEO memory as the source for buffer object operations.
GL CALLBACK:  type = 0x8251, severity = 0x826b, message = Buffer detailed info: Buffer object 7 (bound to GL_ARRAY_BUFFER_ARB, usage hint is GL_STATIC_DRAW) will use VIDEO memory as the source for buffer object operations.
GL CALLBACK:  type = 0x8251, severity = 0x826b, message = Buffer detailed info: Buffer object 8 (bound to GL_ELEMENT_ARRAY_BUFFER_ARB, usage hint is GL_STATIC_DRAW) will use VIDEO memory as the source for buffer object operations.
GL CALLBACK:  type = 0x8251, severity = 0x826b, message = Buffer detailed info: Buffer object 11 (bound to GL_ARRAY_BUFFER_ARB, usage hint is GL_STATIC_DRAW) will use VIDEO memory as the source for buffer object operations.
GL CALLBACK:  type = 0x8251, severity = 0x826b, message = Buffer detailed info: Buffer object 12 (bound to GL_ARRAY_BUFFER_ARB, usage hint is GL_STATIC_DRAW) will use VIDEO memory as the source for buffer object operations.
GL CALLBACK:  type = 0x8251, severity = 0x826b, message = Buffer detailed info: Buffer object 13 (bound to GL_PIXEL_PACK_BUFFER_ARB, usage hint is GL_STREAM_READ) will use DMA CACHED memory as the source for buffer object operations.
GL CALLBACK:  type = 0x8251, severity = 0x826b, message = Buffer detailed info: Buffer object 14 (bound to GL_ARRAY_BUFFER_ARB, usage hint is GL_STATIC_DRAW) will use VIDEO memory as the source for buffer object operations.
GL CALLBACK: ** GL ERROR ** type = 0x824c, severity = 0x9146, message = GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound.
GL CALLBACK: ** GL ERROR ** type = 0x824c, severity = 0x9146, message = GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound.
GL CALLBACK: ** GL ERROR ** type = 0x824c, severity = 0x9146, message = GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound.
GL CALLBACK: ** GL ERROR ** type = 0x824c, severity = 0x9146, message = GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound.
[16470:16516:0512/215414.514699:ERROR:gles2_cmd_decoder.cc(2843)] [.BrowserMainThread-0x9bb750]GL ERROR :GL_INVALID_OPERATION : BackFramebuffer::Destroy: <- error from previous GL command

I always run into "GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound." but only sometimes into Qt's log message " BackFramebuffer::Destroy: <- error from previous GL command".

Hence, it seems to me that "GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound." is much more reliable to reproduce.

I unfortunately cannot conclude whether this is the cause for the Qt log. However, it seems to me that investigating "GL_INVALID_OPERATION error generated. Framebuffer name must be generated before being bound." is interesting in itself as this should not happen? It sounds like a bug in VirtualGL but I am not certain about that?

To answer your questions:
" I would suggest adding a print statement to ~BufferState() to determine the value of oldDrawFBO and oldReadFBO. The error seems to occur when we try to re-bind the FBO that was bound when FakePbuffer::createBuffer() was called. My best guess is that something is killing that FBO in the background, but I have no idea what."

I agree with your assessment of the issue and I am having trouble to find out why the previously bound buffer cannot be rebound. I found out that the values of the draw and read buffers to be restored both are "2" when this happens. Also it seems to me that the issue is not related to the createBuffer code as I can reproduce the same issue with following code modification:

diff --git a/server/backend.cpp b/server/backend.cpp
index 3e02ffc..98a0b5e 100644
--- a/server/backend.cpp
+++ b/server/backend.cpp
@@ -825,6 +825,9 @@ Bool makeCurrent(Display *dpy, GLXDrawable draw, GLXDrawable read,
                        _glGetIntegerv(GL_DRAW_FRAMEBUFFER_BINDING, &drawFBO);
                        _glGetIntegerv(GL_READ_FRAMEBUFFER_BINDING, &readFBO);

+            _glBindFramebuffer(GL_DRAW_FRAMEBUFFER, 0);
+            _glBindFramebuffer(GL_DRAW_FRAMEBUFFER, drawFBO);
+                 
                        if(drawpb) drawpb->createBuffer(false, true);
                        if(readpb && readpb != drawpb) readpb->createBuffer(false, true);

where I just try to bind to the default buffer and back again. I do not understand why this does not work, yet.

Please let me know if you have further suggestions/ideas to this! I will continue digging in the meanwhile.

@dcommander
Copy link
Member

OK, I can now reliably reproduce the low-level OpenGL error. (Not sure why it wasn't showing up yesterday. Probably an error on my part.) I am investigating.

dcommander added a commit that referenced this issue May 14, 2022
- When calling FakePbuffer::createBuffer() from backend::makeCurrent(),
  don't try to re-bind the old FBO if the new FBO will immediately be
  bound.  This fixes a GL_INVALID_OPERATION error that could occur due
  to the following sequence of function calls:

    glXMakeCurrent(dpy, window, context);
    glXMakeCurrent(dpy, 0, 0);
    XDestroyWindow(dpy, window);
    glXMakeCurrent(dpy, other_drawable, context);

  XDestroyWindow() destroys the FakePbuffer instance associated with the
  window, which destroys the FBO and RBOs associated with the
  FakePbuffer instance.  Since XDestroyWindow() is a context-less
  function, the FBO destruction occurs in the RBO context.  However, the
  destroyed FBO is still the current FBO in the application's context.
  The FBO associated with other_drawable will be made current once the
  second glXMake*Current() call completes, so we simply need to avoid
  binding the destroyed FBO within the body of that function call.  The
  easiest way to do that is to avoid restoring an FBO binding via the
  BufferState instance created in FakePbuffer::createBuffer() if that
  binding would immediately be overwritten.

  We do likewise within FakePbuffer:swap(), to fix a similar
  GL_INVALID_OPERATION error in glXSwapBuffers() that was observed
  sporadically in the fakerut multithreaded rendering test.  The exact
  mechanism behind this error was not entirely clear.

- In backend::makeCurrent(), call FakePbuffer::setDrawBuffer() rather
  than FakePbuffer::setDrawBuffers() if ContextHashEGL.getDrawBuffers()
  returns only one buffer.  If ContextHashEGL.getDrawBuffers() returns
  only one buffer, then that buffer may be GL_FRONT or another enum that
  would trigger a GL_INVALID_ENUM error if passed to
  FakePbuffer::setDrawBuffers() (since FakePbuffer::setDrawBuffers()
  emulates the behavior of glDrawBuffers().)

Fixes #199
@dcommander
Copy link
Member

Should be fixed now. Try the latest pre-release build.

@JHagemeister
Copy link
Author

Awesome! I have not seen the error again in ~50 runs on my machine.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants