goroutine hangs at runtime.Gosched()

[kingluo]

The go version is 1.5.1.

Here is the program:

package main

import (
    "fmt"
    "runtime"
    "time"
)

func test2() {
    for i := 1; ; i++ {
        fmt.Println(i, time.Now())
    }
}

func test() {
    a := 100
    for i := 1; i < 1000; i++ {
        a = i*100/i + a
    }
}

func main() {
    runtime.GOMAXPROCS(2)
    go test2()
    for {
        test()
    }
}

Note that I configure two threads to run goroutines.
The main goroutine would block one thread, while the test2() goroutine would run in another thread.
However, the result is that, the test2() runs a bit, but after some random interval, it hangs (do not output anything); the main goroutine continue to run test() without problem.

If I add some function call into the test(), e.g.

func test() {
    ...
    syscall.Getgid()
}

Then the test() and test2() would run in parallel as expected.

I try to do panic after some counts (estimated to be after the test2() hangs) within the loop to call test():

    for i := 1; i < 10000000000; i++ {
        if i == 1000000 {
            panic("hello")
        }
        test()
    }

Then it shows the backtrace:

goroutine 1 [running]:
main.main()
    /tmp/tmp.go:30 +0xb1

goroutine 5 [runnable]:
runtime.Gosched()
    /usr/local/go/src/runtime/proc.go:166 +0x14
time.Time.Format(0xecd820010, 0x37614ae4, 0x593740, 0x523840, 0x27, 0x0, 0x0)
    /usr/local/go/src/time/format.go:431 +0x135
time.Time.String(0xecd820010, 0x37614ae4, 0x593740, 0x0, 0x0)
    /usr/local/go/src/time/format.go:401 +0x54
time.(*Time).String(0xc8204977a0, 0x0, 0x0)
    <autogenerated>:1 +0xad
fmt.(*pp).handleMethods(0xc820068000, 0xc800000076, 0x0, 0xc820071c01)
    /usr/local/go/src/fmt/print.go:730 +0x633
fmt.(*pp).printArg(0xc820068000, 0x5024a0, 0xc8204977a0, 0x76, 0x0, 0xc81ffdb400)
    /usr/local/go/src/fmt/print.go:806 +0x4a5
fmt.(*pp).doPrint(0xc820068000, 0xc820071f78, 0x2, 0x2, 0x101)
    /usr/local/go/src/fmt/print.go:1254 +0x258
fmt.Fprintln(0x7f18e5d2f000, 0xc820026010, 0xc820071f78, 0x2, 0x2, 0x40b7f0, 0x0, 0x0)
    /usr/local/go/src/fmt/print.go:254 +0x67
fmt.Println(0xc820071f78, 0x2, 0x2, 0x5024a0, 0x0, 0x0)
    /usr/local/go/src/fmt/print.go:264 +0x73
main.test2()
    /tmp/tmp.go:12 +0x17f
created by main.main
    /tmp/tmp.go:27 +0x3c
exit status 2

So why test2() goroutine hangs?

[davecheney]

My guess is your program is hanging because the garbage collector cannot run, and the garbage collector cannot run because all goroutines have not stopped.

[randall77]

Dup of #10958

[kingluo]

@randall77 Is this issue really duplicated with #10958? Here I'm wondering why it hangs, while in #10958, I doubt the precise preempt happens at the newstack() but not every function call.

[randall77]

Yes. As Dave said, GC eventually tries to run, successfully stops the goroutine running test2, and then hangs forever trying to stop the goroutine that is doing for { test() }.

[kingluo]

Why removing time.Now() from test2() works? Because then the whole program running would not trigger GC?
In other words, if the program has such infinite blocking loop, and if GC runs, then it would result in hanging?

[randall77]

Removing time.Now() from test2 doesn't work for me. The program still hangs after a while (~250K iterations).

Bottom line, don't write loops like this. Add runtime.Gosched() if you don't have anything else significant in the loop.

[RLH]

If performance is a concern unroll the loop or add an inner loop. Until we
teach our compilers how to do this automatically this work around is the
best advice we can give.

On Wed, Sep 9, 2015 at 11:38 AM, Keith Randall [email protected]
wrote:

Removing time.Now() from test2 doesn't work for me. The program still
hangs after a while (~250K iterations).

Bottom line, don't write loops like this. Add runtime.Gosched() if you
don't have anything else significant in the loop.

—
Reply to this email directly or view it on GitHub
#12553 (comment).

[kingluo]

Yes, removing the time.Now() doesn't work.
The go 1.5.1 would hangs the program at ~250K iteration, and the go 1.3.3 would hangs at ~12million.

Then the backtrace would be:

goroutine 1 [running]:
main.main()
    /tmp/tmp.go:29 +0xb1

goroutine 5 [runnable]:
fmt.Println(0xc82003af80, 0x1, 0x1, 0x4c0c00, 0xc820487020, 0x0)
    /usr/local/go/src/fmt/print.go:263
main.test2()
    /tmp/tmp.go:12 +0xc8
created by main.main
    /tmp/tmp.go:26 +0x3c

Thanks for your advises.

I'm still wondering, the preemption check only happens at newstack(), right?

[davecheney]

@kingluo this issue is closed. If you want to discuss it further, please open a thread on the golang-nuts mailing list.

[randall77]

Preemption checks happen at every function entry point, except those functions which don't have a preemption check (those with small stack frames, not recursive, ...).

The preemption check causes the function entry to call into morestack and then newstack where the preemption is processed.