Golang fmt.Println() causes game crash

Question

I have this simple OpenGL program in Go.

When I compile and run it, the main game-loop gets through about 9 iterations before crashing with a segmentation violation.

rendering for the  0  time
rendering for the  1  time
rendering for the  2  time
rendering for the  3  time
rendering for the  4  time
rendering for the  5  time
rendering for the  6  time
SIGSEGV: segmentation violation
PC=0x7fdab95a0e29
signal arrived during cgo execution

runtime.cgocall(0x414f90, 0x7fdab9887e88)
    /usr/lib/go/src/pkg/runtime/cgocall.c:149 +0x11b fp=0x7fdab9887e70
github.com/go-gl/gl._Cfunc_glClear(0xc200004100)
    github.com/go-gl/gl/_obj/_cgo_defun.c:340 +0x31 fp=0x7fdab9887e88
github.com/go-gl/gl.Clear(0x4100)
    /mnt/data/Dropbox/Coding/Go/src/github.com/go-gl/gl/gl.go:161 +0x25 fp=0x7fdab9887e98
main.draw()
    /home/josh/Coding/Go/src/github.com/JoshWillik/Wander/wander.go:120 +0x25 fp=0x7fdab9887eb8
main.main()
    /home/josh/Coding/Go/src/github.com/JoshWillik/Wander/wander.go:52 +0x300 fp=0x7fdab9887f48
runtime.main()
    /usr/lib/go/src/pkg/runtime/proc.c:220 +0x11f fp=0x7fdab9887fa0
runtime.goexit()
    /usr/lib/go/src/pkg/runtime/proc.c:1394 fp=0x7fdab9887fa8

goroutine 3 [syscall]:
runtime.goexit()
    /usr/lib/go/src/pkg/runtime/proc.c:1394

rax     0x0
rbx     0x7fdab9887e88
rcx     0x7fdab9887e88
rdx     0x7fdab9887e20
rdi     0x4100
rsi     0xc210001900
rbp     0xc21002a000
rsp     0x7fdab2a4ddd8
r8      0xc210001120
r9      0x7fdab9887e20
r10     0x0
r11     0x286
r12     0x0
r13     0x7fdab9a74000
r14     0x0
r15     0x7fdab2a4e700
rip     0x7fdab95a0e29
rflags  0x10202
cs      0x33
fs      0x0
gs      0x0

If I remove the time-based logic in the shouldRender function, it makes it to about 28-29 iterations before crashing.

If I remove the call to gl.Clear() in the draw function, it lasts into the 90s before crashing.

If I remove the call to fmt.Println() in shouldRender, the game runs as expected without crashing. (I've tested it up to about 2 or 3 minutes, so almost 10 thousand frames)

This makes me suspect that the call to fmt.Println() is somehow responsible for the segmentation violation. Am I misreading the signs? If not, how is a core function like Println() so unstable?

package main

import (
    f "fmt"
    "github.com/go-gl/gl"
    glfw "github.com/go-gl/glfw3"
    "math"
    "time"
)

var (
    numRendered = 0
    lastDraw = time.Now()
    fps = 60
    seconds = time.Now()
    attr gl.AttribLocation
)

func main(){
    if !glfw.Init(){
        f.Println("Failed to init glfw")
        panic("Cannot initialize glfw library")
    }
    defer glfw.Terminate()

    //glfw.WindowHint(glfw.DepthBits, 16)
    window, err := glfw.CreateWindow(300, 300, "Wander", nil, nil)
    if err != nil{
        panic(err)
    }

    window.SetFramebufferSizeCallback(reshape)
    window.SetKeyCallback(key)
    window.MakeContextCurrent()
    glfw.SwapInterval(1)
    width, height := window.GetFramebufferSize()
    reshape(window, width, height)

    if gl.Init() != 0 {
        panic("Failed to init GL")
    }

    prog := setupProgram()
    defer prog.Delete()
    prog.Use()

    attr = prog.GetAttribLocation("offset")

    setup()
    for !window.ShouldClose() {
        if shouldRender(){
            draw()
        }
        animate()
        window.SwapBuffers()
        glfw.PollEvents()
    }
}
func setupProgram()(prog gl.Program){
    vertexSource := `
        #version 430 core

        layout (location = 0) in vec4 offset;

        const vec4 vertecies[3] = vec4[3](
            vec4(0.25, 0.5, 0.5, 1.0),
            vec4(-0.25, 0.5, 0.5, 1.0),
            vec4(-0.25, -0.5, 0.5, 1.0)
        );

        void main(){
            gl_Position = vertecies[gl_VertexID] + offset;
        }`
    fragmentSource := `
        #version 430 core

        out vec4 color;

        void main(){
            color = vec4(1.0, 0.0, 0.0, 0.0); // red, blue, green, ??
        }`
    vert, frag := gl.CreateShader(gl.VERTEX_SHADER), gl.CreateShader(gl.FRAGMENT_SHADER)
    defer vert.Delete()
    defer frag.Delete()
    vert.Source(vertexSource)
    frag.Source(fragmentSource)
    vert.Compile()
    frag.Compile()

    prog = gl.CreateProgram()
    prog.AttachShader(vert)
    prog.AttachShader(frag)
    prog.Link()
    prog.Use()
    f.Println(prog.GetInfoLog())

    return
}

func key(window *glfw.Window, k glfw.Key, s int, action glfw.Action, mods glfw.ModifierKey) {
    if action != glfw.Press {
        return
    }

    switch glfw.Key(k){
        case glfw.KeyEscape:
            window.SetShouldClose(true);
        default:
            return
    }
}

func reshape(window *glfw.Window, width, height int){
    gl.Viewport(0, 0, width, height)
}
func draw(){
    gl.Clear(gl.COLOR_BUFFER_BIT | gl.DEPTH_BUFFER_BIT)
    gl.DrawArrays(gl.TRIANGLES, 0, 3)
}
func shouldRender() bool{
    if int(time.Since(lastDraw) * time.Second) >= 1000/fps{
        //f.Println("rendering for the ", numRendered, " time")
        numRendered++
        lastDraw = time.Now()
        return true
    }

    return false;
}

func animate(){
    now := float64(time.Since(seconds))

    offset := [4]float32{
        float32(math.Sin(now)),
        float32(math.Cos(now)),
        0.0,0.0}
    attr.Attrib4fv(&offset)

    red := gl.GLclampf(math.Sin(now) * 0.25 + 0.75)
    blue := gl.GLclampf(math.Cos(now) * 0.25 + 0.75)
    green := gl.GLclampf(time.Since(seconds))
    _ = green;

    gl.ClearColor(red, blue, 0.2, 0.0)
}

Answer 1

I ran your code on my machine -- MinGW-w64 on 64-bit Windows. While my code with the println ran much longer than yours (over 30k calls before crashing) I observed the same behavior.

The stack trace reported it on calls to gl functions, this gave me an inkling: perhaps the error was related to the OpenGL context.

Indeed, if you add

import (
//...
"runtime"
//...
)

And the line

runtime.LockOSThread()

To the top of the main function, the error goes away (or at least with the thread locked it ran several minutes on my machine, obviously I can't prove it will never crash).

When Goroutines are blocked doing certain tasks such as IO, the Go runtime will occasionally split off extra threads to keep the program moving.

I suspect that what it happening is that sometimes on a call to Println, the Goroutine becomes blocked on a syscall, so the runtime "helps" you by running your main goroutine on a different thread. Since OpenGL contexts are bound to a thread, this is causing your program to crash on GL calls because you're calling on the wrong thread.

Adding runtime.LockOSThread() to the top of main forces the main Goroutine to always execute on the same thread, and thus keeps all the GL calls in the correct context.

I should add that I briefly skimmed the source the fmt package and from what I saw I can't prove that the goroutine/thread nonsense is definitely happening; however, I strongly suspect that this is the case based on what I know about the Go runtime and the fact that LockOSThread seems to fix it.

Either way: when you're using a C library such as OpenGL or OpenAL that depends on having a context bound to a single thread, make sure to always lock the Goroutine it's running on to one thread with runtime.LockOSThread.

Update: I found this document on the Go scheduler, which, if I'm reading it correctly, confirms my suspicions. Syscalls such as printing can call new threads to be spawned to allow the calling goroutine to continue while the program is blocked on IO.