LWJGLX/Debug

Yesterday evening I was motivated by this LWJGL3 GitHub issue (and others) to build a small tool (in the form of a JVM Java Agent) that’ll output meaningful errors instead of causing hard JVM crashes when people use LWJGL3/OpenGL in the wrong way.

@Spasi built LWJGL3 to be extremely fast, targeting OpenGL experts who want to build games/engines for the JVM and know what they’re doing.
However, I’d say that 99% of the people coming in first contact with LWJGL, and its recent version 3, are novices and could be demotivated/deterred when they see a hard JVM crash because they did not call GL.createCapabilities().
Don’t get me wrong, LWJGL 3 is totally awesome when you know what you’re doing. But fact is: Most people don’t know what they’re doing. :slight_smile:

That’s why LWJGLX Debug exists now. It’ll enable all debugging capabilities already provided by LWJGL3, configure/enable a OpenGL debugging context/callback and additionally will instrument all GL calls to check:

  1. whether there is a GLCapabilities in the current thread (i.e. whether the user called GL.createCapabilities()/setCapabilities())
  2. whether the GL call is actually supported/exposed by the driver (i.e. whether its GLCapabilities field is not 0L)
  3. performing the GL call
  4. checking the glGetError() and throwing an exception if it is not 0
    (see this integration test which can be executed by calling ./mvnw package)

Especially the first two points are popular sources for JVM crashes and LWJGLX/Debug is meant to provide help here.
Of course, everything will run a lot slower then. But the point is to prevent crashes and tell the user what went wrong.

In my experience our joe sixpack developer (which is the target audience) doesn’t want to understand Java Agents, and will steer clear of any non-obvious commandline parameters.

Even Maven is a bridge too far for most in your target audience. Better just transform the whole LWJGL jar and make that ‘build’ available as a single file.

See: any java-agent backed API / utility on JGO. :emo:

Since yesterday the library has grown significantly and more checks are being added constantly.
In addition to the checks mentioned in the previous post, the following probably more important validations have been added:

  1. check whether enabled vertex attributes have also been properly initialized (this is probably the number 1 issue with OpenGL why client code crashes in a glDraw* call)

  2. for the most frequently used methods taking a NIO Buffer, check whether the buffer is direct, if it has the correct ByteOrder and if it has at least 1 remaining element (those three things have been the reason for some forum.lwjgl.org entries in the past years, especially the last one when users forget to rewind()/flip() the buffer)

  3. support for shared contexts and checking for false sharing of VAOs (other non-shareable GL objects soon to come). Of course, this cannot be covered 100%, since a user could theoretically allocate two different VAOs in two shared contexts, having different meanings/contents and assuming to be able to use the VAO of context A in context B (without checking that they actually have the same handle/integer value)

More validations added:

  • Shader compilation status
  • Program linkage status
  • FBO status check

In addition to that, there is now also an option to output a GL call trace. This allows to quickly narrow a problem down by seeing only the trace of effective GL calls without all the classes/abstractions and method delegations in user code.

The trace prints a counter/identifier of the OpenGL context the call occurred in, the function name and both the actual arguments as well as the return value, and looks something like this for a typical LWJGL3/OpenGL program:


[trace] glfwInit() = true
[trace] glfwDefaultWindowHints()
[trace] glfwWindowHint(131076, 0)
[trace] glfwWindowHint(131075, 0)
[trace] glfwWindowHint(135181, 4)
[trace] glfwGetPrimaryMonitor() = 4141072L
[trace] glfwGetVideoMode(4141072L) = GLFWVidMode pointer [0x3F3034]
[trace] glfwCreateWindow(100, 100, "Little Space Shooter Game", 0L, 0L) = 4213472L
[trace] glfwCreateStandardCursor(221187) = 778060784L
[trace] glfwSetCursor(4213472L, 778060784L)
[trace] glfwSetFramebufferSizeCallback(4213472L,  pointer [0x1F40000]) = null
[trace] glfwSetWindowSizeCallback(4213472L,  pointer [0x1FC0000]) = null
[trace] glfwSetKeyCallback(4213472L,  pointer [0x26C0000]) = null
[trace] glfwSetCursorPosCallback(4213472L,  pointer [0x26D0000]) = null
[trace] glfwSetMouseButtonCallback(4213472L,  pointer [0x26E0000]) = null
[trace][1] glfwMakeContextCurrent(4213472L)
[trace][1] glfwSwapInterval(0)
[trace][1] glfwShowWindow(4213472L)
[trace][1] nglfwGetFramebufferSize(4213472L, 698531808L, 698531812L)
[debug][1] Initialized OpenGL context [1] for GLFW window [4213472L]
[trace][1] createCapabilities() = org.lwjgl.opengl.GLCapabilities@62ee68d8
[trace][1] glGenTextures() = 1
[trace][1] glBindTexture(34067, 1)
[trace][1] glTexParameteri(34067, 10240, 9729)
[trace][1] glTexParameteri(34067, 10241, 9987)
[trace][1] glTexParameteri(34067, 33169, 1)
[trace][1] glTexImage2D(34069, 0, 32849, 2048, 2048, 0, 6407, 5121, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glTexImage2D(34070, 0, 32849, 2048, 2048, 0, 6407, 5121, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glTexImage2D(34071, 0, 32849, 2048, 2048, 0, 6407, 5121, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glTexImage2D(34072, 0, 32849, 2048, 2048, 0, 6407, 5121, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glTexImage2D(34073, 0, 32849, 2048, 2048, 0, 6407, 5121, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glTexImage2D(34074, 0, 32849, 2048, 2048, 0, 6407, 5121, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glEnable(34895)
[trace][1] glCreateShader(35633) = 1
[trace][1] glShaderSource(1, org.lwjgl.PointerBuffer[pos=0 lim=1 cap=1], java.nio.DirectIntBufferU[pos=0 lim=1 cap=1])
[trace][1] glCompileShader(1)
[trace][1] glGetShaderi(1, 35713) = 1
[trace][1] glGetShaderInfoLog(1) = ""
[trace][1] glCreateShader(35632) = 2
...

@Spasi and I are working on the capability of outputting GLenum names for parameters that are GLenums instead of the integer value.

Ooooohhh! Yes, yes, that could be very useful. I have a bug lurking in our multi-windowed editor which I wasn’t able to track down yet, though I believe its some mis-sharing of GL resources.

As usual, my MacBook doesn’t care. My Windows PC spams GL debug errors. On the artist PC it crashes hard.

After lots of frustration about correctly interpreting the metadata in gl.xml, here is the previous output but now with completely automatically resolved GLenum names instead of their integer values!

Thanks to @Spasi for working on the LWJGL 3 side of this by supplying @NativeType annotations on methods and method parameters in the LWJGL 3 sources/classfiles, which allowed to match the LWJGL 3 GL API with the gl.xml metadata in order to identify GLenums and decode them!

And the best thing is: Resolving bitmasks, called GLbitfield in GL, works too (see the glClear() output not shown in the previous output).
Also new and not shown above is tracing of the GLSL code uploaded via the various GL API functions such as glShaderSource() and glCreateShaderProgramv():


[trace] glfwInit() = true
[trace] glfwDefaultWindowHints()
[trace] glfwWindowHint(GLFW_VISIBLE, GLFW_FALSE)
[trace] glfwWindowHint(GLFW_RESIZABLE, GLFW_FALSE)
[trace] glfwWindowHint(GLFW_SAMPLES, 4)
[trace] glfwGetPrimaryMonitor() = 5149680L
[trace] glfwGetVideoMode(5149680L) = GLFWVidMode pointer [0x4E9414]
[trace] glfwCreateWindow(100, 100, "Little Space Shooter Game", 0L, 0L) = 5186608L
[trace] glfwCreateStandardCursor(GLFW_CROSSHAIR_CURSOR) = 854237072L
[trace] glfwSetCursor(5186608L, 854237072L)
[trace] glfwSetFramebufferSizeCallback(5186608L,  pointer [0x1FC0000]) = null
[trace] glfwSetWindowSizeCallback(5186608L,  pointer [0x2550000]) = null
[trace] glfwSetKeyCallback(5186608L,  pointer [0x2930000]) = null
[trace] glfwSetCursorPosCallback(5186608L,  pointer [0x2940000]) = null
[trace] glfwSetMouseButtonCallback(5186608L,  pointer [0x2950000]) = null
[trace][1] glfwMakeContextCurrent(5186608L)
[trace][1] glfwSwapInterval(0)
[trace][1] glfwShowWindow(5186608L)
[trace][1] nglfwGetFramebufferSize(5186608L, 695713168L, 695713172L)
[info ][1] Initialized OpenGL context [1] for GLFW window [5186608L]
[trace][1] createCapabilities() = org.lwjgl.opengl.GLCapabilities@3581c5f3
[trace][1] glGenTextures() = 1
[trace][1] glBindTexture(GL_TEXTURE_CUBE_MAP, 1)
[trace][1] glTexParameteri(GL_TEXTURE_CUBE_MAP, GL_TEXTURE_MAG_FILTER, 9729)
[trace][1] glTexParameteri(GL_TEXTURE_CUBE_MAP, GL_TEXTURE_MIN_FILTER, 9987)
[trace][1] glTexParameteri(GL_TEXTURE_CUBE_MAP, GL_GENERATE_MIPMAP, 1)
[trace][1] glTexImage2D(GL_TEXTURE_CUBE_MAP_POSITIVE_X, 0, GL_RGB8, 2048, 2048, 0, GL_RGB, GL_UNSIGNED_BYTE, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glTexImage2D(GL_TEXTURE_CUBE_MAP_NEGATIVE_X, 0, GL_RGB8, 2048, 2048, 0, GL_RGB, GL_UNSIGNED_BYTE, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glTexImage2D(GL_TEXTURE_CUBE_MAP_POSITIVE_Y, 0, GL_RGB8, 2048, 2048, 0, GL_RGB, GL_UNSIGNED_BYTE, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glTexImage2D(GL_TEXTURE_CUBE_MAP_NEGATIVE_Y, 0, GL_RGB8, 2048, 2048, 0, GL_RGB, GL_UNSIGNED_BYTE, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glTexImage2D(GL_TEXTURE_CUBE_MAP_POSITIVE_Z, 0, GL_RGB8, 2048, 2048, 0, GL_RGB, GL_UNSIGNED_BYTE, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glTexImage2D(GL_TEXTURE_CUBE_MAP_NEGATIVE_Z, 0, GL_RGB8, 2048, 2048, 0, GL_RGB, GL_UNSIGNED_BYTE, java.nio.DirectByteBuffer[pos=0 lim=12582912 cap=12582912])
[trace][1] glEnable(GL_TEXTURE_CUBE_MAP_SEAMLESS)
[trace][1] glCreateShader(GL_VERTEX_SHADER) = 1
[trace][1] Shader source for shader [1]:
        1  /*
        2   * Copyright LWJGL. All rights reserved.
        3   * License terms: http://lwjgl.org/license.php
        4   */
        5  #version 110
        6  
        7  uniform mat4 invViewProj;
        8  
        9  varying vec3 dir;
       10  
       11  void main(void) {
...
[trace][1] glShaderSource(1, org.lwjgl.PointerBuffer[pos=0 lim=1 cap=1], java.nio.DirectIntBufferU[pos=0 lim=1 cap=1])
[trace][1] glCompileShader(1)
[trace][1] glGetShaderi(1, GL_COMPILE_STATUS) = 1
[trace][1] glGetShaderInfoLog(1) = ""
[trace][1] glCreateShader(GL_FRAGMENT_SHADER) = 2
...
[trace][1] glClear(GL_COLOR_BUFFER_BIT | GL_DEPTH_BUFFER_BIT)
[trace][1] glUseProgram(6)
[trace][1] glBindBuffer(GL_ARRAY_BUFFER, 1)
[trace][1] glVertexPointer(3, GL_FLOAT, 0, 0L)
[trace][1] glEnableClientState(GL_NORMAL_ARRAY)
[trace][1] glBindBuffer(GL_ARRAY_BUFFER, 2)
...

There are some places here and there in the GL API, which require manual GLenum decoding, such as the 9729 and 9987 in glTexParameteri(), since those are only enums depending on the pname parameter. For this, it is now also simple to define a custom trace method doing the resolution and parameter/return value printing.
The majority of the remaining work will be providing manual GLenum resolution for those cases.

Added source file and line number information to the log output, which is recognized by the IDEs and clickable to navigate to the respective source line.
Example trace of the LWJGL 3 Getting Started example:


[trace] (HelloWorld.java:40)       glfwInit() = true
[trace] (HelloWorld.java:44)       glfwDefaultWindowHints()
[trace] (HelloWorld.java:45)       glfwWindowHint(GLFW_VISIBLE, GLFW_FALSE)
[trace] (HelloWorld.java:46)       glfwWindowHint(GLFW_RESIZABLE, GLFW_TRUE)
[trace] (HelloWorld.java:49)       glfwCreateWindow(300, 300, "Hello World!", 0L, 0L) = 3507968L
[trace] (HelloWorld.java:54)       glfwSetKeyCallback(3507968L, HelloWorld$$Lambda$9/2007328737@736e9adb) = null
[trace] (HelloWorld.java:65)       glfwGetWindowSize(3507968L, java.nio.DirectIntBufferU[pos=0 lim=1 cap=1], java.nio.DirectIntBufferU[pos=0 lim=1 cap=1])
[trace] (HelloWorld.java:68)       glfwGetPrimaryMonitor() = 3474480L
[trace] (HelloWorld.java:68)       glfwGetVideoMode(3474480L) = GLFWVidMode pointer [0x350454]
[trace] (HelloWorld.java:71)       glfwSetWindowPos(3507968L, 810, 450)
[trace][1] (HelloWorld.java:79)       glfwMakeContextCurrent(3507968L)
[trace][1] (HelloWorld.java:81)       glfwSwapInterval(1)
[trace][1] (HelloWorld.java:84)       glfwShowWindow(3507968L)
[trace][1] (HelloWorld.java:93)       createCapabilities() = org.lwjgl.opengl.GLCapabilities@15327b79
[trace][1] (HelloWorld.java:96)       glClearColor(1.0f, 0.0f, 0.0f, 0.0f)
[trace][1] (HelloWorld.java:100)      glfwWindowShouldClose(3507968L) = false
[trace][1] (HelloWorld.java:101)      glClear(GL_COLOR_BUFFER_BIT | GL_DEPTH_BUFFER_BIT)
[trace][1] (HelloWorld.java:103)      glfwSwapBuffers(3507968L)
[trace][1] (HelloWorld.java:107)      glfwPollEvents()
[trace][1] (HelloWorld.java:100)      glfwWindowShouldClose(3507968L) = false

When inside the Console view of Eclipse, the “HelloWorld.java:number” are navigatable links just like Stacktrace elements.

I was looking for something exactly like this (stack trace of to calls) a while back. Would be good to have a post about this on the lwjgl forums and to have it integrated with the lwjgl downloads if possible. The more seemless it can become the more it will be used

More work done on LWJGLX/debug this day:

  • added semantic information to GLFWwindow and GLFWmonitor parameters and return values (not showing the pointer address but a “window[1]” or “monitor[0]” message for parameters and return values so that people do not need to compare pointer addresses)
  • added the option to redirect LWJGL and LWJGLX/debug log and trace output to a file via -Dorg.lwjglx.OUTPUT (LWJGL log output is redirected using the -Dorg.lwjgl.util.DebugStream mechanism already provided by LWJGL3)
  • when the log/trace output file name ends with .zip or .gz a corresponding archive is created (to dramatically reduce the footprint of the trace file on the filesystem)
  • improved runtime performance of the proxy class generator (now only generating a class per callsite class with only the LWJGL3 methods actually being called by user code instead of ALL methods in all used LWJGL3 classes)
  • added automatic buffer argument checks (instead of writing the checks in manual validation methods)
  • changed how NIO Buffers are printed in trace
  • some few bugfixes

Output for the LWJGL3 HelloWorld example now:


[trace] (HelloWorld.java:40)  glfwInit() = true
[trace] (HelloWorld.java:44)  glfwDefaultWindowHints()
[trace] (HelloWorld.java:45)  glfwWindowHint(GLFW_VISIBLE, GLFW_FALSE)
[trace] (HelloWorld.java:46)  glfwWindowHint(GLFW_RESIZABLE, GLFW_TRUE)
[trace] (HelloWorld.java:49)  glfwCreateWindow(300, 300, "Hello World!", 0L, 0L) = window[1]
[trace] (HelloWorld.java:54)  glfwSetKeyCallback(window[1], test.HelloWorld$$Lambda$11/1297685781@65ae6ba4) = null
[trace] (HelloWorld.java:65)  glfwGetWindowSize(window[1], IntBuffer[0x28f65cec, 1], IntBuffer[0x28f65ce8, 1])
[trace] (HelloWorld.java:68)  glfwGetPrimaryMonitor() = monitor[0]
[trace] (HelloWorld.java:68)  glfwGetVideoMode(monitor[0]) = GLFWVidMode pointer [0x5A3354]
[trace] (HelloWorld.java:71)  glfwSetWindowPos(window[1], 810, 450)
[trace][1] (HelloWorld.java:79)  glfwMakeContextCurrent(window[1])
[trace][1] (HelloWorld.java:81)  glfwSwapInterval(1)  // 59 Hz
[trace][1] (HelloWorld.java:84)  glfwShowWindow(window[1])
[info ][1] Initialized OpenGL context for window[1]
[trace][1] (HelloWorld.java:93)  createCapabilities() = org.lwjgl.opengl.GLCapabilities@2d3fcdbd
[trace][1] (HelloWorld.java:96)  glClearColor(1.0f, 0.0f, 0.0f, 0.0f)
[trace][1] (HelloWorld.java:100) glfwWindowShouldClose(window[1]) = false
[trace][1] (HelloWorld.java:101) glClear(GL_COLOR_BUFFER_BIT | GL_DEPTH_BUFFER_BIT)
[trace][1] (HelloWorld.java:103) glfwSwapBuffers(window[1])
[trace][1] (HelloWorld.java:107) glfwPollEvents()
[trace][1] (HelloWorld.java:100) glfwWindowShouldClose(window[1]) = false
...
[trace][1] (HelloWorld.java:100) glfwWindowShouldClose(window[1]) = true
[trace][1] (HelloWorld.java:26)  glfwFreeCallbacks(window[1])
[info ] Destroying OpenGL context for window[1]
[trace] (HelloWorld.java:27)  glfwDestroyWindow(window[1])
[trace] (HelloWorld.java:30)  glfwTerminate()
[trace] (HelloWorld.java:31)  glfwSetErrorCallback(null) =  pointer [0x2B0000]

Thanks to @Spasi and @ap0stolos, LWJGLX/debug can now be selected as an Addon in the “Addons” section of the LWJGL 3 download page.

Additionally, I began implementing video capture with FFmpeg/libavcodec, recording the framebuffer of every created GLFW window in a HEVC encoded mp4 file, for visual debugging without having to do “animated gifs” or using other proprietary/commercial or limited software such as fraps when all that is needed is to capture the contents of a GLFW window for a few seconds or minutes.

Here is an uninteresting 13 seconds video showing the 300x300 red window of the LWJGL Getting Started program: https://www.dropbox.com/s/9ec394fr8bdluoj/capture.mp4?dl=0

LWJGLX/Debug is getting a profiling mode with a simple Web frontend (powered by the awesome Chart.js library) which looks like this:

(example of running the SpaceGame demo in the lwjgl-demos repository)

Example of a Buffer Object “memory leak”:

EDIT:
New metric “Draw GPU (ms.)” which is the total time for all draw calls measured in GPU time using ARB_timer_query:

EDIT:
New GPU timing of designated code sections (the bottom graph) via GL_GREMEDY_string_marker now also supported by LWJGL3: