Deadlocks in Go

(and how to break out of them)

By George Aristy / llorllale

Extending my previous talk on Golang Concurrency Patterns.

Topics

What deadlocks are
When deadlocks typically happen
How Go's runtime detects deadlocks
Go's stacktraces
Tools

References

What are deadlocks?

A state where no process can proceed because each is waiting on another process (including themselves).
In Go, these "processes" are goroutines .

Goroutines are deadlocked when...

There is lock contention.
Attempting to read from an empty or nil channel .
Attempting to write to a channel with a full buffer.

Example deadlocks


package main

import "sync"

func main() {
    muA := sync.Mutex{}
    muB := sync.Mutex{}

    // main goroutine acquires both locks
    muA.Lock()
    muB.Lock()

    // first sub goroutine attempts to lock "B" before releasing "A".
    go func() {
        defer muA.Unlock()
        muB.Lock()
    }()

    // second sub goroutine attempts to lock "A" before releasing "B".
    go func() { // second sub goroutine
        defer muB.Unlock()
        muA.Lock()
    }()

    // third sub goroutine attempts to read from an empty channel that is never written to
    go func() {
        empty := make(chan struct{})
        <-empty
    }()

    // fourth sub goroutine attempts to read from a nil channel
    go func() {
        var c chan struct{}
        <-c
    }()

    // main goroutine blocked trying to write to an unbuffered channel
    make(chan struct{}) <- struct{}{}
}


package main

import "sync"

func main() {
    muA := sync.Mutex{}
    muB := sync.Mutex{}

    // main goroutine acquires both locks
    muA.Lock()
    muB.Lock()

    // first sub goroutine attempts to lock "B" before releasing "A".
    go func() {
        defer muA.Unlock()
        muB.Lock()
    }()

    // second sub goroutine attempts to lock "A" before releasing "B".
    go func() { // second sub goroutine
        defer muB.Unlock()
        muA.Lock()
    }()

    // third sub goroutine attempts to read from an empty channel that is never written to
    go func() {
        empty := make(chan struct{})
        <-empty
    }()

    // fourth sub goroutine attempts to read from a nil channel
    go func() {
        var c chan struct{}
        <-c
    }()

    // main goroutine blocked trying to write to an unbuffered channel
    make(chan struct{}) <- struct{}{}
}


package main

import "sync"

func main() {
    muA := sync.Mutex{}
    muB := sync.Mutex{}

    // main goroutine acquires both locks
    muA.Lock()
    muB.Lock()

    // first sub goroutine attempts to lock "B" before releasing "A".
    go func() {
        defer muA.Unlock()
        muB.Lock()
    }()

    // second sub goroutine attempts to lock "A" before releasing "B".
    go func() { // second sub goroutine
        defer muB.Unlock()
        muA.Lock()
    }()

    // third sub goroutine attempts to read from an empty channel that is never written to
    go func() {
        empty := make(chan struct{})
        <-empty
    }()

    // fourth sub goroutine attempts to read from a nil channel
    go func() {
        var c chan struct{}
        <-c
    }()

    // main goroutine blocked trying to write to an unbuffered channel
    make(chan struct{}) <- struct{}{}
}


package main

import "sync"

func main() {
    muA := sync.Mutex{}
    muB := sync.Mutex{}

    // main goroutine acquires both locks
    muA.Lock()
    muB.Lock()

    // first sub goroutine attempts to lock "B" before releasing "A".
    go func() {
        defer muA.Unlock()
        muB.Lock()
    }()

    // second sub goroutine attempts to lock "A" before releasing "B".
    go func() { // second sub goroutine
        defer muB.Unlock()
        muA.Lock()
    }()

    // third sub goroutine attempts to read from an empty channel that is never written to
    go func() {
        empty := make(chan struct{})
        <-empty
    }()

    // fourth sub goroutine attempts to read from a nil channel
    go func() {
        var c chan struct{}
        <-c
    }()

    // main goroutine blocked trying to write to an unbuffered channel
    make(chan struct{}) <- struct{}{}
}


package main

import "sync"

func main() {
    muA := sync.Mutex{}
    muB := sync.Mutex{}

    // main goroutine acquires both locks
    muA.Lock()
    muB.Lock()

    // first sub goroutine attempts to lock "B" before releasing "A".
    go func() {
        defer muA.Unlock()
        muB.Lock()
    }()

    // second sub goroutine attempts to lock "A" before releasing "B".
    go func() { // second sub goroutine
        defer muB.Unlock()
        muA.Lock()
    }()

    // third sub goroutine attempts to read from an empty channel that is never written to
    go func() {
        empty := make(chan struct{})
        <-empty
    }()

    // fourth sub goroutine attempts to read from a nil channel
    go func() {
        var c chan struct{}
        <-c
    }()

    // main goroutine blocked trying to write to an unbuffered channel
    make(chan struct{}) <- struct{}{}
}


package main

import "sync"

func main() {
    muA := sync.Mutex{}
    muB := sync.Mutex{}

    // main goroutine acquires both locks
    muA.Lock()
    muB.Lock()

    // first sub goroutine attempts to lock "B" before releasing "A".
    go func() {
        defer muA.Unlock()
        muB.Lock()
    }()

    // second sub goroutine attempts to lock "A" before releasing "B".
    go func() { // second sub goroutine
        defer muB.Unlock()
        muA.Lock()
    }()

    // third sub goroutine attempts to read from an empty channel that is never written to
    go func() {
        empty := make(chan struct{})
        <-empty
    }()

    // fourth sub goroutine attempts to read from a nil channel
    go func() {
        var c chan struct{}
        <-c
    }()

    // main goroutine blocked trying to write to an unbuffered channel
    make(chan struct{}) <- struct{}{}
}


package main

import "sync"

func main() {
    muA := sync.Mutex{}
    muB := sync.Mutex{}

    // main goroutine acquires both locks
    muA.Lock()
    muB.Lock()

    // first sub goroutine attempts to lock "B" before releasing "A".
    go func() {
        defer muA.Unlock()
        muB.Lock()
    }()

    // second sub goroutine attempts to lock "A" before releasing "B".
    go func() { // second sub goroutine
        defer muB.Unlock()
        muA.Lock()
    }()

    // third sub goroutine attempts to read from an empty channel that is never written to
    go func() {
        empty := make(chan struct{})
        <-empty
    }()

    // fourth sub goroutine attempts to read from a nil channel
    go func() {
        var c chan struct{}
        <-c
    }()

    // main goroutine blocked trying to write to an unbuffered channel
    make(chan struct{}) <- struct{}{}
}

Something nasty happens:


fatal error: all goroutines are asleep - deadlock!

goroutine 1 [chan send]:
main.main()
        /home/llorllale/scratchpad/main.go:38 +0x169

goroutine 6 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000220a0)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func1()
        /home/llorllale/scratchpad/main.go:16 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:14 +0xe5

goroutine 7 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc000022098)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func2()
        /home/llorllale/scratchpad/main.go:22 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:20 +0x139

goroutine 8 [chan receive]:
main.main.func3()
        /home/llorllale/scratchpad/main.go:28 +0x2c
created by main.main
        /home/llorllale/scratchpad/main.go:26 +0x145

goroutine 9 [chan receive (nil chan)]:
main.main.func4()
        /home/llorllale/scratchpad/main.go:34 +0x1d
created by main.main
        /home/llorllale/scratchpad/main.go:32 +0x151

Let's break that error down.

Stacktraces in Go

The Go runtime yells that all goroutines are blocked:


fatal error: all goroutines are asleep - deadlock!

goroutine 1 [chan send]:
main.main()
        /home/llorllale/scratchpad/main.go:38 +0x169

goroutine 6 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000220a0)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func1()
        /home/llorllale/scratchpad/main.go:16 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:14 +0xe5

goroutine 7 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc000022098)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func2()
        /home/llorllale/scratchpad/main.go:22 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:20 +0x139

goroutine 8 [chan receive]:
main.main.func3()
        /home/llorllale/scratchpad/main.go:28 +0x2c
created by main.main
        /home/llorllale/scratchpad/main.go:26 +0x145

goroutine 9 [chan receive (nil chan)]:
main.main.func4()
        /home/llorllale/scratchpad/main.go:34 +0x1d
created by main.main
        /home/llorllale/scratchpad/main.go:32 +0x151

main goroutine is blocked trying to send to a channel:


fatal error: all goroutines are asleep - deadlock!

goroutine 1 [chan send]:
main.main()
        /home/llorllale/scratchpad/main.go:38 +0x169

goroutine 6 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000220a0)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func1()
        /home/llorllale/scratchpad/main.go:16 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:14 +0xe5

goroutine 7 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc000022098)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func2()
        /home/llorllale/scratchpad/main.go:22 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:20 +0x139

goroutine 8 [chan receive]:
main.main.func3()
        /home/llorllale/scratchpad/main.go:28 +0x2c
created by main.main
        /home/llorllale/scratchpad/main.go:26 +0x145

goroutine 9 [chan receive (nil chan)]:
main.main.func4()
        /home/llorllale/scratchpad/main.go:34 +0x1d
created by main.main
        /home/llorllale/scratchpad/main.go:32 +0x151

first sub goroutine is blocked trying to acquire a lock:


fatal error: all goroutines are asleep - deadlock!

goroutine 1 [chan send]:
main.main()
        /home/llorllale/scratchpad/main.go:38 +0x169

goroutine 6 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000220a0)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func1()
        /home/llorllale/scratchpad/main.go:16 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:14 +0xe5

goroutine 7 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc000022098)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func2()
        /home/llorllale/scratchpad/main.go:22 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:20 +0x139

goroutine 8 [chan receive]:
main.main.func3()
        /home/llorllale/scratchpad/main.go:28 +0x2c
created by main.main
        /home/llorllale/scratchpad/main.go:26 +0x145

goroutine 9 [chan receive (nil chan)]:
main.main.func4()
        /home/llorllale/scratchpad/main.go:34 +0x1d
created by main.main
        /home/llorllale/scratchpad/main.go:32 +0x151

second sub goroutine is blocked trying to acquire a lock:


fatal error: all goroutines are asleep - deadlock!

goroutine 1 [chan send]:
main.main()
        /home/llorllale/scratchpad/main.go:38 +0x169

goroutine 6 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000220a0)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func1()
        /home/llorllale/scratchpad/main.go:16 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:14 +0xe5

goroutine 7 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc000022098)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func2()
        /home/llorllale/scratchpad/main.go:22 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:20 +0x139

goroutine 8 [chan receive]:
main.main.func3()
        /home/llorllale/scratchpad/main.go:28 +0x2c
created by main.main
        /home/llorllale/scratchpad/main.go:26 +0x145

goroutine 9 [chan receive (nil chan)]:
main.main.func4()
        /home/llorllale/scratchpad/main.go:34 +0x1d
created by main.main
        /home/llorllale/scratchpad/main.go:32 +0x151

third sub goroutine is stuck waiting to receive on a channel:


fatal error: all goroutines are asleep - deadlock!

goroutine 1 [chan send]:
main.main()
        /home/llorllale/scratchpad/main.go:38 +0x169

goroutine 6 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000220a0)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func1()
        /home/llorllale/scratchpad/main.go:16 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:14 +0xe5

goroutine 7 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc000022098)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func2()
        /home/llorllale/scratchpad/main.go:22 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:20 +0x139

goroutine 8 [chan receive]:
main.main.func3()
        /home/llorllale/scratchpad/main.go:28 +0x2c
created by main.main
        /home/llorllale/scratchpad/main.go:26 +0x145

goroutine 9 [chan receive (nil chan)]:
main.main.func4()
        /home/llorllale/scratchpad/main.go:34 +0x1d
created by main.main
        /home/llorllale/scratchpad/main.go:32 +0x151

fourth sub goroutine is stuck waiting to receive on a nil channel:


fatal error: all goroutines are asleep - deadlock!

goroutine 1 [chan send]:
main.main()
        /home/llorllale/scratchpad/main.go:38 +0x169

goroutine 6 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc0000220a0)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func1()
        /home/llorllale/scratchpad/main.go:16 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:14 +0xe5

goroutine 7 [semacquire]:
sync.runtime_SemacquireMutex(0x0?, 0x0?, 0x0?)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc000022098)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
        /home/llorllale/.gvm/gos/go1.19/src/sync/mutex.go:90
main.main.func2()
        /home/llorllale/scratchpad/main.go:22 +0x72
created by main.main
        /home/llorllale/scratchpad/main.go:20 +0x139

goroutine 8 [chan receive]:
main.main.func3()
        /home/llorllale/scratchpad/main.go:28 +0x2c
created by main.main
        /home/llorllale/scratchpad/main.go:26 +0x145

goroutine 9 [chan receive (nil chan)]:
main.main.func4()
        /home/llorllale/scratchpad/main.go:34 +0x1d
created by main.main
        /home/llorllale/scratchpad/main.go:32 +0x151

Go's stacktrace format:


goroutine 21 [chan receive (nil chan)]:                <=== wait reason
main.main.func4(0x0?)
        /home/llorllale/scratchpad/main.go:34 +0x1b
created by main.main
        /home/llorllale/scratchpad/main.go:33 +0x173

Wait reasons .


goroutine 21 [chan receive (nil chan)]:
main.main.func4(0x0?)                                  <=== FQN of func + args
        /home/llorllale/scratchpad/main.go:34 +0x1b    <=== file + line no.
created by main.main
        /home/llorllale/scratchpad/main.go:33 +0x173


goroutine 21 [chan receive (nil chan)]:
main.main.func4(0x0?)
        /home/llorllale/scratchpad/main.go:34 +0x1b
created by main.main                                   <=== ancestor
        /home/llorllale/scratchpad/main.go:33 +0x173   <=== ancestor definition

Go's runtime detects deadlocks

"fatal error: all goroutines are asleep - deadlock!" - Go runtime
Triggered only when *all* goroutines are blocked (too late, so not too useful...)
Triggered if:
- There are no free worker threads , and:
- If no processor has future work scheduled .
- Source: checkdead()
Recall prior overview of the scheduler

Tools

pprof

Your Swiss Army Knife.

pprof

Enable it:

```diff diff --git a/cmd/api/main.go b/cmd/api/main.go index bec2bf16..dab3d03f 100644 --- a/cmd/api/main.go +++ b/cmd/api/main.go @@ -2,11 +2,15 @@ package main import ( + "net/http" + _ "net/http/pprof" ) func main() { @@ -16,6 +20,10 @@ func main() { + go func() { + log.Println(http.ListenAndServe(":6060", nil)) // debug handler + }() ```

pprof

View stacktraces at http://localhost:6060/debug/pprof/goroutine?debug=1:

```shell goroutine profile: total 29 10 @ 0x43bff6 0x44bd9c 0x1132ba5 0x46ce01 # 0x1132ba4 cloud.google.com/go/spanner.(*healthChecker).worker+0x344 /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/cloud.google.com/go/spanner@v1.38.0/session.go:1556 4 @ 0x43bff6 0x434a77 0x467349 0x4d7292 0x4d85fa 0x4d85e8 0x5d2189 0x5e4565 0x6645db 0x4afb5a 0x76b1ee 0x76b1a8 0x76ba55 0x8d3f7e 0x46ce01 # 0x467348 internal/poll.runtime_pollWait+0x88 /home/llorllale/.gvm/gos/go1.19/src/runtime/netpoll.go:305 # 0x4d7291 internal/poll.(*pollDesc).wait+0x31 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_poll_runtime.go:84 # 0x4d85f9 internal/poll.(*pollDesc).waitRead+0x259 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_poll_runtime.go:89 # 0x4d85e7 internal/poll.(*FD).Read+0x247 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_unix.go:167 # 0x5d2188 net.(*netFD).Read+0x28 /home/llorllale/.gvm/gos/go1.19/src/net/fd_posix.go:55 # 0x5e4564 net.(*conn).Read+0x44 /home/llorllale/.gvm/gos/go1.19/src/net/net.go:183 # 0x6645da bufio.(*Reader).Read+0x1ba /home/llorllale/.gvm/gos/go1.19/src/bufio/bufio.go:237 # 0x4afb59 io.ReadAtLeast+0x99 /home/llorllale/.gvm/gos/go1.19/src/io/io.go:332 # 0x76b1ed io.ReadFull+0x6d /home/llorllale/.gvm/gos/go1.19/src/io/io.go:351 # 0x76b1a7 golang.org/x/net/http2.readFrameHeader+0x27 /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/golang.org/x/net@v0.0.0-20220722155237-a158d28d115b/http2/frame.go:237 # 0x76ba54 golang.org/x/net/http2.(*Framer).ReadFrame+0x94 /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/golang.org/x/net@v0.0.0-20220722155237-a158d28d115b/http2/frame.go:498 # 0x8d3f7d google.golang.org/grpc/internal/transport.(*http2Client).reader+0x4bd /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/google.golang.org/grpc@v1.49.0/internal/transport/http2_client.go:1503 4 @ 0x43bff6 0x44bd9c 0x8bfb55 0x8c0265 0x8c9c6a 0x46ce01 # 0x8bfb54 google.golang.org/grpc/internal/transport.(*controlBuffer).get+0x114 /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/google.golang.org/grpc@v1.49.0/internal/transport/controlbuf.go:408 # 0x8c0264 google.golang.org/grpc/internal/transport.(*loopyWriter).run+0x84 /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/google.golang.org/grpc@v1.49.0/internal/transport/controlbuf.go:535 # 0x8c9c69 google.golang.org/grpc/internal/transport.newHTTP2Client.func3+0x69 /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/google.golang.org/grpc@v1.49.0/internal/transport/http2_client.go:417 4 @ 0x43bff6 0x44bd9c 0x93b2f3 0x46ce01 # 0x93b2f2 google.golang.org/grpc.(*ccBalancerWrapper).watcher+0x72 /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/google.golang.org/grpc@v1.49.0/balancer_conn_wrappers.go:112 1 @ 0x4314f6 0x466ea5 0x98f895 0x98f6ad 0x98c5cb 0x137e905 0x137f49e 0x6e266f 0x6e4009 0x6e5a6c 0x6e1147 0x46ce01 # 0x466ea4 runtime/pprof.runtime_goroutineProfileWithLabels+0x24 /home/llorllale/.gvm/gos/go1.19/src/runtime/mprof.go:846 # 0x98f894 runtime/pprof.writeRuntimeProfile+0xb4 /home/llorllale/.gvm/gos/go1.19/src/runtime/pprof/pprof.go:723 # 0x98f6ac runtime/pprof.writeGoroutine+0x4c /home/llorllale/.gvm/gos/go1.19/src/runtime/pprof/pprof.go:683 # 0x98c5ca runtime/pprof.(*Profile).WriteTo+0x14a /home/llorllale/.gvm/gos/go1.19/src/runtime/pprof/pprof.go:330 # 0x137e904 net/http/pprof.handler.ServeHTTP+0x4a4 /home/llorllale/.gvm/gos/go1.19/src/net/http/pprof/pprof.go:253 # 0x137f49d net/http/pprof.Index+0x13d /home/llorllale/.gvm/gos/go1.19/src/net/http/pprof/pprof.go:371 # 0x6e266e net/http.HandlerFunc.ServeHTTP+0x2e /home/llorllale/.gvm/gos/go1.19/src/net/http/server.go:2109 # 0x6e4008 net/http.(*ServeMux).ServeHTTP+0x148 /home/llorllale/.gvm/gos/go1.19/src/net/http/server.go:2487 # 0x6e5a6b net/http.serverHandler.ServeHTTP+0x30b /home/llorllale/.gvm/gos/go1.19/src/net/http/server.go:2947 # 0x6e1146 net/http.(*conn).serve+0x606 /home/llorllale/.gvm/gos/go1.19/src/net/http/server.go:1991 1 @ 0x43bff6 0x434a77 0x467349 0x4d7292 0x4d85fa 0x4d85e8 0x5d2189 0x5e4565 0x6daedf 0x46ce01 # 0x467348 internal/poll.runtime_pollWait+0x88 /home/llorllale/.gvm/gos/go1.19/src/runtime/netpoll.go:305 # 0x4d7291 internal/poll.(*pollDesc).wait+0x31 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_poll_runtime.go:84 # 0x4d85f9 internal/poll.(*pollDesc).waitRead+0x259 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_poll_runtime.go:89 # 0x4d85e7 internal/poll.(*FD).Read+0x247 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_unix.go:167 # 0x5d2188 net.(*netFD).Read+0x28 /home/llorllale/.gvm/gos/go1.19/src/net/fd_posix.go:55 # 0x5e4564 net.(*conn).Read+0x44 /home/llorllale/.gvm/gos/go1.19/src/net/net.go:183 # 0x6daede net/http.(*connReader).backgroundRead+0x3e /home/llorllale/.gvm/gos/go1.19/src/net/http/server.go:678 1 @ 0x43bff6 0x434a77 0x467349 0x4d7292 0x4dc514 0x4dc501 0x5d4295 0x5ed9a8 0x5eca1d 0x7aaf1d 0x66106d 0x6e5fc5 0x7a98c5 0x13637c9 0x1380925 0x43bc32 0x46ce01 # 0x467348 internal/poll.runtime_pollWait+0x88 /home/llorllale/.gvm/gos/go1.19/src/runtime/netpoll.go:305 # 0x4d7291 internal/poll.(*pollDesc).wait+0x31 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_poll_runtime.go:84 # 0x4dc513 internal/poll.(*pollDesc).waitRead+0x233 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_poll_runtime.go:89 # 0x4dc500 internal/poll.(*FD).Accept+0x220 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_unix.go:614 # 0x5d4294 net.(*netFD).accept+0x34 /home/llorllale/.gvm/gos/go1.19/src/net/fd_unix.go:172 # 0x5ed9a7 net.(*TCPListener).accept+0x27 /home/llorllale/.gvm/gos/go1.19/src/net/tcpsock_posix.go:142 # 0x5eca1c net.(*TCPListener).AcceptTCP+0x3c /home/llorllale/.gvm/gos/go1.19/src/net/tcpsock.go:275 # 0x7aaf1c github.com/labstack/echo/v4.tcpKeepAliveListener.Accept+0x1c /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/github.com/labstack/echo/v4@v4.9.0/echo.go:957 # 0x66106c crypto/tls.(*listener).Accept+0x2c /home/llorllale/.gvm/gos/go1.19/src/crypto/tls/tls.go:66 # 0x6e5fc4 net/http.(*Server).Serve+0x384 /home/llorllale/.gvm/gos/go1.19/src/net/http/server.go:3070 # 0x7a98c4 github.com/labstack/echo/v4.(*Echo).StartServer+0x84 /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/github.com/labstack/echo/v4@v4.9.0/echo.go:745 # 0x13637c8 github.com/some-org/some-repo/cmd/api/server.(*Server).StartTLS+0xe8 /home/llorllale/dev/some-org/some-repo/cmd/api/server/server.go:36 # 0x1380924 main.main+0x1e4 /home/llorllale/dev/some-org/some-repo/cmd/api/main.go:47 # 0x43bc31 runtime.main+0x211 /home/llorllale/.gvm/gos/go1.19/src/runtime/proc.go:250 1 @ 0x43bff6 0x434a77 0x467349 0x4d7292 0x4dc514 0x4dc501 0x5d4295 0x5ed9a8 0x5ecb7d 0x6e5fc5 0x6e5bfd 0x13806e5 0x13806b5 0x46ce01 # 0x467348 internal/poll.runtime_pollWait+0x88 /home/llorllale/.gvm/gos/go1.19/src/runtime/netpoll.go:305 # 0x4d7291 internal/poll.(*pollDesc).wait+0x31 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_poll_runtime.go:84 # 0x4dc513 internal/poll.(*pollDesc).waitRead+0x233 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_poll_runtime.go:89 # 0x4dc500 internal/poll.(*FD).Accept+0x220 /home/llorllale/.gvm/gos/go1.19/src/internal/poll/fd_unix.go:614 # 0x5d4294 net.(*netFD).accept+0x34 /home/llorllale/.gvm/gos/go1.19/src/net/fd_unix.go:172 # 0x5ed9a7 net.(*TCPListener).accept+0x27 /home/llorllale/.gvm/gos/go1.19/src/net/tcpsock_posix.go:142 # 0x5ecb7c net.(*TCPListener).Accept+0x3c /home/llorllale/.gvm/gos/go1.19/src/net/tcpsock.go:288 # 0x6e5fc4 net/http.(*Server).Serve+0x384 /home/llorllale/.gvm/gos/go1.19/src/net/http/server.go:3070 # 0x6e5bfc net/http.(*Server).ListenAndServe+0x7c /home/llorllale/.gvm/gos/go1.19/src/net/http/server.go:2999 # 0x13806e4 net/http.ListenAndServe+0x44 /home/llorllale/.gvm/gos/go1.19/src/net/http/server.go:3255 # 0x13806b4 main.main.func2+0x14 /home/llorllale/dev/some-org/some-repo/cmd/api/main.go:24 1 @ 0x43bff6 0x44bd9c 0x11338ed 0x46ce01 # 0x11338ec cloud.google.com/go/spanner.(*healthChecker).maintainer+0x40c /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/cloud.google.com/go/spanner@v1.38.0/session.go:1619 1 @ 0x43bff6 0x44bd9c 0x9a10ad 0x46ce01 # 0x9a10ac go.opencensus.io/stats/view.(*worker).start+0xac /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/go.opencensus.io@v0.23.0/stats/view/worker.go:276 1 @ 0x43bff6 0x44bd9c 0x9eda65 0x46ce01 # 0x9eda64 github.com/facebookgo/muster.(*Client).worker+0x224 /home/llorllale/.gvm/pkgsets/go1.19/global/pkg/mod/github.com/facebookgo/muster@v0.0.0-20150708232844-fd3d7953fd52/muster.go:165 ```

pprof

Trace execution:

wget -O trace.out http://localhost:6060/debug/pprof/trace?seconds=5

pprof

Trace execution:

wget -O trace.out http://localhost:6060/debug/pprof/trace?seconds=5
go tool trace ./trace.out

pprof

Trace execution: pprof_trace

pprof

CPU profile:

wget -O profile.out http://localhost:6060/debug/pprof/profile?seconds=5

pprof

CPU profile:

wget -O profile.out http://localhost:6060/debug/pprof/profile?seconds=5
go tool pprof ./profile.out

pprof

CPU profile:

```shell File: main-api Type: cpu Time: Sep 21, 2022 at 6:53am (EDT) Duration: 5s, Total samples = 100ms ( 2.00%) Entering interactive mode (type "help" for commands, "o" for options) (pprof) top Showing nodes accounting for 100ms, 100% of 100ms total Showing top 10 nodes out of 13 flat flat% sum% cum cum% 40ms 40.00% 40.00% 40ms 40.00% runtime.epollwait 10ms 10.00% 50.00% 20ms 20.00% cloud.google.com/go/spanner.(*healthChecker).worker.func1 10ms 10.00% 60.00% 10ms 10.00% cloud.google.com/go/spanner.(*session).getNextCheck 10ms 10.00% 70.00% 70ms 70.00% runtime.findRunnable 10ms 10.00% 80.00% 10ms 10.00% runtime.makechan 10ms 10.00% 90.00% 50ms 50.00% runtime.netpoll 10ms 10.00% 100% 10ms 10.00% runtime.stealWork 0 0% 100% 30ms 30.00% cloud.google.com/go/spanner.(*healthChecker).worker 0 0% 100% 70ms 70.00% runtime.mcall 0 0% 100% 70ms 70.00% runtime.park_m ```

pprof

CPU profile (graph):
pprof_profile_graph

panicparse

Friendlier tracing:

```diff diff --git a/cmd/api/server/init.go b/cmd/api/server/init.go index 071bc782..7ee8c3c0 100644 --- a/cmd/api/server/init.go +++ b/cmd/api/server/init.go @@ -2,6 +2,7 @@ package api import ( + "github.com/maruel/panicparse/v2/stack/webstack" @@ -65,6 +66,11 @@ func InitServer() *Server + a.Echo.GET("/debug/panicparse", func(c echo.Context) error { + webstack.SnapshotHandler(c.Response(), c.Request()) + return nil + }) ```

panicparse

Go to http://{localhost}/debug/panicparse:

sasha-s/go-deadlock

Detect potential deadlocks on inconsistent lock ordering:


package main

import (
    sync "github.com/sasha-s/go-deadlock"
    "time"
)

func main() {
    sync.Opts.DeadlockTimeout = time.Second

    var A sync.Mutex
    var B sync.Mutex

    A.Lock()
    B.Lock()

    go func() {
        defer A.Unlock()
        B.Lock()
    }()

    go func() {
        defer B.Unlock()
        A.Lock()
    }()

    for {
        time.Sleep(time.Second)
    }
}

sasha-s/go-deadlock

Output:


POTENTIAL DEADLOCK:
Previous place where the lock was grabbed
goroutine 1 lock 0xc000022090
sasha-deadlock/main.go:16 main.main {  } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }
~/.gvm/gos/go1.19/src/runtime/proc.go:258 runtime.main { // Once it does, it will exit. See issues 3934 and 20018. }

Have been trying to lock it again for more than 1s
goroutine 8 lock 0xc000022090
sasha-deadlock/main.go:19 main.main.func1 { B.Lock() } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }

Here is what goroutine 1 doing now
goroutine 1 [sleep]:
time.Sleep(0x2540be400)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/time.go:195 +0x135
main.main()
        /home/llorllale/scratchpad/sasha-deadlock/main.go:28 +0x165
Other goroutines holding locks:
goroutine 1 lock 0xc000022078
sasha-deadlock/main.go:14 main.main { A.Lock() } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }
~/.gvm/gos/go1.19/src/runtime/proc.go:258 runtime.main { // Once it does, it will exit. See issues 3934 and 20018. }

sasha-s/go-deadlock

Who holds the lock:


POTENTIAL DEADLOCK:
Previous place where the lock was grabbed
goroutine 1 lock 0xc000022090
sasha-deadlock/main.go:16 main.main {  } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }
~/.gvm/gos/go1.19/src/runtime/proc.go:258 runtime.main { // Once it does, it will exit. See issues 3934 and 20018. }

Have been trying to lock it again for more than 1s
goroutine 8 lock 0xc000022090
sasha-deadlock/main.go:19 main.main.func1 { B.Lock() } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }

Here is what goroutine 1 doing now
goroutine 1 [sleep]:
time.Sleep(0x2540be400)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/time.go:195 +0x135
main.main()
        /home/llorllale/scratchpad/sasha-deadlock/main.go:28 +0x165
Other goroutines holding locks:
goroutine 1 lock 0xc000022078
sasha-deadlock/main.go:14 main.main { A.Lock() } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }
~/.gvm/gos/go1.19/src/runtime/proc.go:258 runtime.main { // Once it does, it will exit. See issues 3934 and 20018. }

sasha-s/go-deadlock

Who wants the lock:


POTENTIAL DEADLOCK:
Previous place where the lock was grabbed
goroutine 1 lock 0xc000022090
sasha-deadlock/main.go:16 main.main {  } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }
~/.gvm/gos/go1.19/src/runtime/proc.go:258 runtime.main { // Once it does, it will exit. See issues 3934 and 20018. }

Have been trying to lock it again for more than 1s
goroutine 8 lock 0xc000022090
sasha-deadlock/main.go:19 main.main.func1 { B.Lock() } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }

Here is what goroutine 1 doing now
goroutine 1 [sleep]:
time.Sleep(0x2540be400)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/time.go:195 +0x135
main.main()
        /home/llorllale/scratchpad/sasha-deadlock/main.go:28 +0x165
Other goroutines holding locks:
goroutine 1 lock 0xc000022078
sasha-deadlock/main.go:14 main.main { A.Lock() } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }
~/.gvm/gos/go1.19/src/runtime/proc.go:258 runtime.main { // Once it does, it will exit. See issues 3934 and 20018. }

sasha-s/go-deadlock

What everyone is doing:


POTENTIAL DEADLOCK:
Previous place where the lock was grabbed
goroutine 1 lock 0xc000022090
sasha-deadlock/main.go:16 main.main {  } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }
~/.gvm/gos/go1.19/src/runtime/proc.go:258 runtime.main { // Once it does, it will exit. See issues 3934 and 20018. }

Have been trying to lock it again for more than 1s
goroutine 8 lock 0xc000022090
sasha-deadlock/main.go:19 main.main.func1 { B.Lock() } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }

Here is what goroutine 1 doing now
goroutine 1 [sleep]:
time.Sleep(0x2540be400)
        /home/llorllale/.gvm/gos/go1.19/src/runtime/time.go:195 +0x135
main.main()
        /home/llorllale/scratchpad/sasha-deadlock/main.go:28 +0x165
Other goroutines holding locks:
goroutine 1 lock 0xc000022078
sasha-deadlock/main.go:14 main.main { A.Lock() } <<<<<
~/go/pkg/mod/github.com/sasha-s/go-deadlock@v0.3.1/deadlock.go:84 go-deadlock.(*Mutex).Lock { func (m *Mutex) Lock() { }
~/.gvm/gos/go1.19/src/runtime/proc.go:258 runtime.main { // Once it does, it will exit. See issues 3934 and 20018. }

Deadlocks in Go

Topics

References

What are deadlocks?

Goroutines are deadlocked when...

Example deadlocks

Stacktraces in Go

Go's stacktrace format:

Go's runtime detects deadlocks

Tools

pprof

pprof

pprof

pprof

pprof

pprof

pprof

pprof

pprof

pprof

pprof

panicparse

panicparse

panicparse

sasha-s/go-deadlock

sasha-s/go-deadlock

sasha-s/go-deadlock

sasha-s/go-deadlock

sasha-s/go-deadlock

sasha-s/go-deadlock

Questions?