audio playback locks whole game since newest patches

[w33zl3p00tch]

First of all, thank you very much for releasing ebiten! I'm currently learning how to use it.

The issue: I have a function that looks like this:

func slowPrint(m string) {
        clkSnd, err := wav.Decode(audioContext, audio.BytesReadSeekCloser(sounds.Click1Wav))
        check(err)
        audioPlayer, err = audio.NewPlayer(audioContext, clkSnd)
        check(err)
        play := func() {
                if audioPlayer.IsPlaying() {
                        return
                } else {
                        audioPlayer.Rewind()
                        audioPlayer.Play()
                }
        }
        lastC := ""
        for _, c := range m {
                for gameIsPaused {
                        time.Sleep(time.Second / 2)
                }
                msg += string(c)
                if string(c) != "\n" && soundOn {
                        play()
                }

                time.Sleep(time.Second / 24)
                if (string(c) == "\n" && lastC == ".") || string(c) == "." {
                        time.Sleep(time.Second / 2)
                }
                lastC = string(c)
        }
}

// check does not abort/print anything in this context :(
func check(err error) {
        if err != nil {
                log.Fatal(err)
        }
}

When it gets called for long strings, at some point the playback seems to lock up and never finish. This is only like that since the last updates. When I check out commit cce41e8152e3b425bedcef683ae52c19adcfaffb , everything works fine again. Please let me know what you need to investigate this further, or, if I'm doing something wrong, feel free to point it out to me.

[hajimehoshi]

Hi, thank you for reporting!

Would it be possible to know a minimal code to reproduce this problem? I'll try to make it based on your code, but I'd be happy if you already had one.

[hajimehoshi]

package main

import (
    "log"
    "time"

    "github.com/hajimehoshi/ebiten"
    "github.com/hajimehoshi/ebiten/audio"
    "github.com/hajimehoshi/ebiten/audio/wav"
    raudio "github.com/hajimehoshi/ebiten/examples/resources/audio"
)

var (
    audioContext *audio.Context
    audioPlayer  *audio.Player
    msg          = ""
)

const (
    soundOn      = true
    gameIsPaused = false
)

func init() {
    var err error
    audioContext, err = audio.NewContext(44100)
    if err != nil {
        panic(err)
    }
}

func slowPrint(m string) {
    clkSnd, err := wav.Decode(audioContext, audio.BytesReadSeekCloser(raudio.Jab_wav))
    check(err)
    audioPlayer, err = audio.NewPlayer(audioContext, clkSnd)
    check(err)
    play := func() {
        if audioPlayer.IsPlaying() {
            return
        } else {
            audioPlayer.Rewind()
            audioPlayer.Play()
        }
    }
    lastC := ""
    for _, c := range m {
        for gameIsPaused {
            time.Sleep(time.Second / 2)
        }
        msg += string(c)
        if string(c) != "\n" && soundOn {
            play()
        }

        time.Sleep(time.Second / 24)
        if (string(c) == "\n" && lastC == ".") || string(c) == "." {
            time.Sleep(time.Second / 2)
        }
        lastC = string(c)
    }
}

// check does not abort/print anything in this context :(
func check(err error) {
    if err != nil {
        log.Fatal(err)
    }
}

func run(screen *ebiten.Image) error {
    slowPrint("hello")
    return nil
}

func main() {
    if err := ebiten.Run(run, 320, 240, 2, ""); err != nil {
        log.Fatal(err)
    }
}

I could not reproduce the freezing. Which environment are you using?

[hajimehoshi]

                if (string(c) == "\n" && lastC == ".") || string(c) == "." {
                        time.Sleep(time.Second / 2)
                }

I have a question around this code: does this mean waiting for (1/2 [s]) in a frame (1/60 [s])? Or, is it safe since slowPrint is called in another goroutine than the main game goroutine?

[w33zl3p00tch]

                if (string(c) == "\n" && lastC == ".") || string(c) == "." {
                        time.Sleep(time.Second / 2)
                }

I have a question around this code: does this mean waiting for (1/2 [s]) in a frame (1/60 [s])? Or, is it safe since slowPrint is called in another goroutine than the main game goroutine?

It is called from another independent goroutine. I will test it later and try to make a minimal example if you haven't fixed it already with your latest changes. I am testing on Linux amd64.

[hajimehoshi]

It is called from another independent goroutine. I will test it later and try to make a minimal example if you haven't fixed it already with your latest changes.

I've fixed another problem that players cause deadlock, which I am not sure is the same issue you reported.

[hajimehoshi]

Then, could you try the latest Ebiten? Thanks!

[w33zl3p00tch]

Okay, I can reproduce the behaviour with ebiten e19479d243ad5678cbdda6487e879fb3e0749da0

I have attached a minimal example bug.go.gz . Compiled and tested with go1.12.1 linux/amd64 native and with GOOS=windows GOARCH=amd64 go build bug.go

On my machine, I have to wait a while before it locks up. Usually about 2-4 iterations of printSomeText().

Here is the code without the audio bytes:

package main

import (
    "github.com/hajimehoshi/ebiten"
    "github.com/hajimehoshi/ebiten/audio"
    "github.com/hajimehoshi/ebiten/audio/wav"
    "github.com/hajimehoshi/ebiten/ebitenutil"
    "log"
    "time"
)

var (
    dimX         = 960
    dimY         = 540
    msg          = ""
    sampleRate   = 44100
    audioContext *audio.Context
    audioPlayer  *audio.Player
)

func init() {
    var err error
    audioContext, err = audio.NewContext(sampleRate)
    check(err)
    ebiten.SetCursorVisibility(false)
}

func slowPrint(m string) {
    clkSnd, err := wav.Decode(audioContext, audio.BytesReadSeekCloser(Click1Wav))
    check(err)
    audioPlayer, err = audio.NewPlayer(audioContext, clkSnd)
    check(err)
    play := func() {
        if audioPlayer.IsPlaying() {
            return
        } else {
            audioPlayer.Rewind()
            audioPlayer.Play()
        }
    }
    lastC := ""
    for _, c := range m {
        for gameIsPaused {
            time.Sleep(time.Second / 2)
        }
        msg += string(c)
        if string(c) != "\n" && soundOn {
            play()
        }

        time.Sleep(time.Second / 24)
        if (string(c) == "\n" && lastC == ".") || string(c) == "." {
            time.Sleep(time.Second / 2)
        }
        lastC = string(c)
    }
}

func printSomeText() {
    msg = ""
    m := `This is a long string that will get repeated until something locks up.
I have no idea what causes this.
Blabla this a long string.
If this gets repeated often enough, eventually this will stop to get printed.
`
    slowPrint(m)
    running = false
}

var soundOn = true // when this is false, there seems no lockup happening
var initialScreenScale = float64(1)
var gameIsPaused = false
var running = false

func update(screen *ebiten.Image) error {
    if !running {
        running = true
        go func() { printSomeText() }()
    }

    if ebiten.IsDrawingSkipped() {
        return nil
    }

    ebitenutil.DebugPrint(screen, msg)

    return nil
}

func main() {
    if err := ebiten.Run(update, dimX, dimY, initialScreenScale, "where is the bug?"); err != nil {
        log.Fatal(err)
    }
}

func check(err error) {
    if err != nil {
        log.Fatal(err)
    }
}

[w33zl3p00tch]

Update: I am pretty confident that this bug has been introduced with 835497edd36c6dc62b29186ad281d4133ebf0f94

With any commits before that, the example runs fine.

[w33zl3p00tch]

Update2: something tells me that the deferred p.m.Unlock() does not get called reliably:

func (p *playerImpl) closeImpl() error {
        p.m.Lock()
        defer p.m.Unlock()          
        if !p.runningReadLoop {          
                return nil
        }
        p.runningReadLoop = false

        p.closeCh <- struct{}{}
        <-p.closedCh
        return nil
}

This works all the time:

func (p *playerImpl) closeImpl() error {
        p.m.Lock()
        r := p.runningReadLoop  
        p.m.Unlock()  
        if !r {
                return nil
        }
        p.runningReadLoop = false

        p.closeCh <- struct{}{}
        <-p.closedCh
        return nil
}

Some printing for debugging:

func (p *playerImpl) closeImpl() error {
        p.m.Lock()

        print("ping?\n")
        defer func() {
                print("pong!\n")
                p.m.Unlock()
        }()                  
        if !p.runningReadLoop {
                return nil
        }
        p.runningReadLoop = false
        print("p.closeCh\n")
        p.closeCh <- struct{}{}   
        print("p.closedCh\n")
        <-p.closedCh
        return nil
}

Output:

[... snip]
ping?
p.closeCh
p.closedCh
pong!
ping?
p.closeCh
p.closedCh
pong!
ping?
p.closeCh
*hangs*

In my output, the last "p.closedCh" and "pong!" is missing, when it locks up. So, my guess is, at some point closeImpl() does not return properly (maybe p.closeCh is locked/blocking?)

[hajimehoshi]

Though I could not reproduce the hung, I am sure that there is an issue in closeImpl. I'll fix this soon...

[hajimehoshi]

Though I could not reproduce the hung,

I could reproduce with 2-3 iterations. Thank you very much!

[hajimehoshi]

Update: I am pretty confident that this bug has been introduced with 835497e

As the change is already reverted, my guess is that this exposed a potential problem and the root cause was in a different location.

something tells me that the deferred p.m.Unlock() does not get called reliably:

I found the similar lock usage is in Seek, and I think this is the cause.

[hajimehoshi]

I think the problem was fixed. https://github.com/hajimehoshi/ebiten/issues/855#issuecomment-487733350 was a great help to me to investigate the problem. I appreciate your cooperation!

[w33zl3p00tch]

Thank you. I've tested it again and it is fixed now.