time.Sleep under 300us causes ATSAMD21 to freeze in some circumstances

[bgould]

Go version: go version go1.12.9 linux/amd64 Tinygo version: tinygo version 0.8.0-dev linux/amd64 (commit 8a5fa51f6023ef78a7e33767a06d68ddea89dfdb)

This program will cause Itsy Bitsy M0 to freeze up after println("about to sleep"):

package main

import (
        "fmt"
        "time"
)

func main() {
        for i := 0; ; i++ {
                if i > 0 && i%10 == 0 {
                        println("about to sleep")
                        time.Sleep(30 * time.Microsecond)
                        println("waking up")
                }
                fmt.Printf("tick %d\r\n", i)
                time.Sleep(1 * time.Second)
        }
}

With trial and error I found that increasing the sleep duration to something around 300us or so allows the program to work as expected; anything less seems to leading to the freezing behavior.

Based on advice from @jadr2ddude I tried enabling schedulerDebug = true in src/runtime/scheduler.go but there was no output. This led me to add an empty goroutine which not only caused the scheduleDebug messages to be outputted as expected, but it evidently causes the above code to work without freezing:

package main

import (
        "fmt"
        "time"
)

func main() {
        go func() {
        }()
        for i := 0; ; i++ {
                if i > 0 && i%10 == 0 {
                        println("about to sleep")
                        time.Sleep(30 * time.Microsecond)
                        println("waking up")
                }
                fmt.Printf("tick %d\r\n", i)
                time.Sleep(1 * time.Second)
        }
}

It appears that when the scheduler is not activate in the program, short sleeps as shown above are not working. I should note as well that I tested this with https://github.com/tinygo-org/tinygo/pull/513 and those changes appear to have solved the problem.

[conejoninja]

go version go1.12.3 linux/amd64 tinygo version 0.8.0-dev linux/amd64

I could confirm this bug, it happens on the Nano33-iot too, this program stops at 213

package main

import "time"

func main() {

    // give us some time so we could attach to the output
    println("GOING TO WAIT A FEW SECONDS")
    time.Sleep(1*time.Second)
    time.Sleep(1*time.Second)
    time.Sleep(1*time.Second)
    time.Sleep(1*time.Second)
    println("ENOUGH WAITING")

    // it stops at 213
    for i := 1000; i > 0; i-- {
        println(i)
        time.Sleep(time.Duration(i) * time.Microsecond)
    }
}

Oddly enough, this program freeze at the 5 seconds sleep too ("ENOUGH WAITING" is not reached) :

package main

import "time"

func main() {

    // give us some time so we could attach to the output
    println("GOING TO WAIT A FEW SECONDS")
    time.Sleep(5*time.Second)
    println("ENOUGH WAITING")

    // it stops at 213
    for i := 1000; i > 0; i-- {
        println(i)
        time.Sleep(time.Duration(i) * time.Microsecond)
    }
}

[deadprogram]

It is probably timing, but not specific to 300us. Here is another test case:

package main

import (
    "time"
)

func printer() {
    c := 0
    for {
        println("main print", c)
        c++
        time.Sleep(1000 * time.Millisecond)
    }
}

func printsubs() {
    c := 0
    for {
        println("sub print", c)
        c++
        time.Sleep(750 * time.Millisecond)
    }
}

func printsubs2() {
    c := 0
    for {
        println("sub print 2", c)
        c++
        time.Sleep(800 * time.Millisecond)
    }
}

func main() {
    go printer()
    go printsubs()
    go printsubs2()
    select {}
}

Which results in this output:

...
sub print 3
sub print 2 3
main print 3
sub print 2 4
sub print 2 5
sub print 2 6
sub print 2 7
sub print 2 8
sub print 2 9
...

After just a few iterations, only the printsubs2 go routine is still running.

[deadprogram]

This is the case with the current dev as well as the last release. You can also reproduce with the TinyGo Playground.

UPDATE: By which I mean that this problem is not specific to the SAMD21 probably.

[conejoninja]

I did not have this issue with the microbit (if that helps), but didn't really test it. I discovered this issue while trying to use the hub75 driver with the nano33, it has a 100µs Sleep at some point and it just freezes. The same example works fine running on a microbit

[niaow]

After debugging a bit, it appears that some values inside the scheduler are being mysteriously changed for no apparent reason. The sleep time remaining on the next task goes negative, and stuff breaks.

[niaow]

I believe that I have fixed the bug here: https://github.com/jadr2ddude/tinygo/commit/d354e1a19f436b2749db649866ce11a95a8d6867

Please confirm that this works for you and I can eventually get a PR in.

[niaow]

Has this been fixed on dev?

[deadprogram]

The current dev branch still has the reported problems.

The jadr2ddude-bufchan branch, the originally reported code works:

package main

import (
        "fmt"
        "time"
)

func main() {
        for i := 0; ; i++ {
                if i > 0 && i%10 == 0 {
                        println("about to sleep")
                        time.Sleep(30 * time.Microsecond)
                        println("waking up")
                }
                fmt.Printf("tick %d\r\n", i)
                time.Sleep(1 * time.Second)
        }
}

However, the code reported by @conejoninja still fails, but instead of failing at 213, it fails consistently at 396:

package main

import "time"

func main() {

    // give us some time so we could attach to the output
    println("GOING TO WAIT A FEW SECONDS")
    time.Sleep(1*time.Second)
    time.Sleep(1*time.Second)
    time.Sleep(1*time.Second)
    time.Sleep(1*time.Second)
    println("ENOUGH WAITING")

    // it stops at 213
    for i := 1000; i > 0; i-- {
        println(i)
        time.Sleep(time.Duration(i) * time.Microsecond)
    }
}

Hopefully that can help track it down...

[deadprogram]

PR #567 should address the remaining problems in this issue.

[deadprogram]

This fix is now in v0.8.0 so I am going to close this issue. Thanks, everyone!