Golang 游戏leaf系列(八) 输出错误日志stacktrace

func destroy(m *module) {
    defer func() {
        if r := recover(); r != nil {
            if conf.LenStackBuf > 0 {
                buf := make([]byte, conf.LenStackBuf)
                l := runtime.Stack(buf, false)
                log.Error("%v: %s", r, buf[:l])
            } else {
                log.Error("%v", r)
            }
        }
    }()

    m.mi.OnDestroy()
}

参考配置conf.LenStackBuf=4096，这段关于错误处理的代码，在leaf别的地方也有遇到，到底是干啥的

Stack trace是指堆栈回溯信息，在当前时间，以当前方法的执行点开始，回溯调用它的方法的方法的执行点，然后继续回溯，这样就可以跟踪整个方法的调用,大家比较熟悉的是JDK所带的jstack工具，可以把Java的所有线程的stack trace都打印出来。
它有什么用呢？用处非常的大，当应用出现一些状况的时候，比如某个模块不执行，锁竞争、CPU占用非常高等问题，又没有足够的log信息可以分析，那么可以查看stack trace信息，看看线程都被阻塞或者运行在那些代码上，然后定位问题所在。

一、正常情况下输出stacktrace

1.runtime/debug.PrintStack()打出当前goroutine的stacktrace

package main

import (
    "fmt"
    "runtime/debug"
)

func test1() {
    test2()
}

func test2() {
    test3()
}

func test3() {
    fmt.Printf("%s", debug.Stack())
    debug.PrintStack()
}

func main() {
    test1()
}
-----------
$ go run test_stacktrace.go

goroutine 1 [running]:
runtime/debug.Stack(0x0, 0x0, 0x0)
        /usr/lib/golang/src/runtime/debug/stack.go:24 +0x80
main.test3()
        /tmp/test_stacktrace.go:17 +0x24
main.test2()
        /tmp/test_stacktrace.go:13 +0x14
main.test1()
        /tmp/test_stacktrace.go:9 +0x14
main.main()
        /tmp/test_stacktrace.go:22 +0x14

从上面代码可以看出，可以通过 debug.PrintStack() 直接打印，也可以通过 debug.Stack() 方法获取堆栈然后自己打印。

2.pprof打印出所有goroutine的 stacktrace

package main
import (
    "os"
    "runtime/pprof"
    "time"
)
func main() {
    go a()
    m1()
}
func m1() {
    m2()
}
func m2() {
    m3()
}
func m3() {
    pprof.Lookup("goroutine").WriteTo(os.Stdout, 1)
    time.Sleep(time.Hour)
}
func a() {
    time.Sleep(time.Hour)
}

3.通过系统信号

runtime.Stack

为了更方便的随时的得到应用所有的goroutine的stack trace信息，我们可以监听SIGUSER1信号，当收到这个信号的时候就将stack trace打印出来。发送信号也很简单，通过kill -SIGUSER1 <pid>就可以，不必担心kill会将程序杀死，它只是发了一个信号而已。

package main
import (
    "fmt"
    "os"
    "os/signal"
    "runtime"
    "syscall"
    "time"
)
func main() {
    setupSigusr1Trap()
    go a()
    m1()
}
func m1() {
    m2()
}
func m2() {
    m3()
}
func m3() {
    time.Sleep(time.Hour)
}
func a() {
    time.Sleep(time.Hour)
}
func setupSigusr1Trap() {
    c := make(chan os.Signal, 1)
    signal.Notify(c, syscall.SIGUSR1)
    go func() {
        for range c {
            DumpStacks()
        }
    }()
}
func DumpStacks() {
    buf := make([]byte, 16384)
    buf = buf[:runtime.Stack(buf, true)]
    fmt.Printf("=== BEGIN goroutine stack dump ===\n
    %s\n=== END goroutine stack dump ===", buf)
}

这是docker代码库中的一段代码，很简单，也很强大。

runtime.Stack(buf, true)

现在看看leaf那段代码，能看懂了吧

defer func() {
    if r := recover(); r != nil {
        if conf.LenStackBuf > 0 {
            buf := make([]byte, conf.LenStackBuf)
            l := runtime.Stack(buf, false)
            log.Error("%v: %s", r, buf[:l])
        } else {
            log.Error("%v", r)
        }
    }
}()

如果有错误需要recover，就把stacktrace内容输出到log.Error里。

二、异常退出情况下输出stacktrace

1.通过panic

如果应用中有没recover的panic,或者应用在运行的时候出现运行时的异常，那么程序自动会将当前的goroutine的stack trace打印出来。比如下面的程序，如果你运行会抛出一个panic。

package main
import (
    "time"
)
func main() {
    go a()
    m1()
}
func m1() {
    m2()
}
func m2() {
    m3()
}
func m3() {
    panic("panic from m3")
}
func a() {
    time.Sleep(time.Hour)
}
-----------------------------

dump go run p.go
panic: panic from m3
goroutine 1 [running]:
panic(0x596a0, 0xc42000a1a0)
    /usr/local/Cellar/go/1.7.4/libexec/src/runtime/panic.go:500 +0x1a1
main.m3()
    /Users/yuepan/go/src/github.com/smallnest/dump/p.go:21 +0x6d
main.m2()
    /Users/yuepan/go/src/github.com/smallnest/dump/p.go:17 +0x14
main.m1()
    /Users/yuepan/go/src/github.com/smallnest/dump/p.go:13 +0x14
main.main()
    /Users/yuepan/go/src/github.com/smallnest/dump/p.go:9 +0x3a
exit status 2

从这个信息中我们可以看到p.go的第9行是main方法，它在这一行调用m1方法，m1方法在第13行调用m2方法，m2方法在第17行调用m3方法，m3方法在第21出现panic，它们运行在goroutine 1中，当前goroutine 1的状态是running状态。

如果想让它把所有的goroutine信息都输出出来，可以设置 GOTRACEBACK=1:

GOTRACEBACK=1 go run p.go
panic: panic from m3
goroutine 1 [running]:
panic(0x596a0, 0xc42000a1b0)
    /usr/local/Cellar/go/1.7.4/libexec/src/runtime/panic.go:500 +0x1a1
main.m3()
    /Users/yuepan/go/src/github.com/smallnest/dump/p.go:21 +0x6d
main.m2()
    /Users/yuepan/go/src/github.com/smallnest/dump/p.go:17 +0x14
main.m1()
    /Users/yuepan/go/src/github.com/smallnest/dump/p.go:13 +0x14
main.main()
    /Users/yuepan/go/src/github.com/smallnest/dump/p.go:9 +0x3a
goroutine 4 [sleep]:
time.Sleep(0x34630b8a000)
    /usr/local/Cellar/go/1.7.4/libexec/src/runtime/time.go:59 +0xe1
main.a()
    /Users/yuepan/go/src/github.com/smallnest/dump/p.go:25 +0x30
created by main.main
    /Users/yuepan/go/src/github.com/smallnest/dump/p.go:8 +0x35
exit status 2

同样你也可以分析这个stack trace的信息，得到方法调用点的情况，同时这个信息将两个goroutine的stack trace都打印出来了，而且goroutine 4的状态是sleep状态。

Go官方文档对这个环境变量有介绍：

The GOTRACEBACK variable controls the amount of output generated when a Go program fails due to an unrecovered panic or an unexpected runtime condition. By default, a failure prints a stack trace for the current goroutine, eliding functions internal to the run-time system, and then exits with exit code 2. The failure prints stack traces for all goroutines if there is no current goroutine or the failure is internal to the run-time. GOTRACEBACK=none omits the goroutine stack traces entirely. GOTRACEBACK=single (the default) behaves as described above. GOTRACEBACK=all adds stack traces for all user-created goroutines. GOTRACEBACK=system is like “all” but adds stack frames for run-time functions and shows goroutines created internally by the run-time. GOTRACEBACK=crash is like “system” but crashes in an operating system-specific manner instead of exiting. For example, on Unix systems, the crash raises SIGABRT to trigger a core dump. For historical reasons, the GOTRACEBACK settings 0, 1, and 2 are synonyms for none, all, and system, respectively. The runtime/debug package's SetTraceback function allows increasing the amount of output at run time, but it cannot reduce the amount below that specified by the environment variable. See https://golang.org/pkg/runtime/debug/#SetTraceback.

你可以设置 none、all、system、single、crash，历史原因，你可以设置数字0、1、2，分别代表none、all、system。

2.通过SIGQUIT信号

如果程序没有发生panic,但是程序有问题，"假死“不工作，我们想看看哪儿出现了问题，可以给程序发送SIGQUIT信号，也可以输出stack trace信息。
比如下面的程序:

package main
import (
    "time"
)
func main() {
    go a()
    m1()
}
func m1() {
    m2()
}
func m2() {
    m3()
}
func m3() {
    time.Sleep(time.Hour)
}
func a() {
    time.Sleep(time.Hour)
}

你可以运行kill -SIGQUIT <pid> 杀死这个程序，程序在退出的时候输出strack trace。