Golang 游戲leaf系列(八) 輸出錯誤日志stacktrace

Golang 游戲leaf系列(七) 監(jiān)聽關(guān)閉的destroy中看到如下代碼

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脊髓,這段關(guān)于錯誤處理的代碼脱茉,在leaf別的地方也有遇到大莫,到底是干啥的

參考
調(diào)試?yán)鳎篸ump goroutine 的 stacktrace

Stack trace是指堆椄岱桑回溯信息,在當(dāng)前時間枝誊,以當(dāng)前方法的執(zhí)行點開始,回溯調(diào)用它的方法的方法的執(zhí)行點惜纸,然后繼續(xù)回溯叶撒,這樣就可以跟蹤整個方法的調(diào)用,大家比較熟悉的是JDK所帶的jstack工具,可以把Java的所有線程的stack trace都打印出來耐版。
它有什么用呢痊乾?用處非常的大,當(dāng)應(yīng)用出現(xiàn)一些狀況的時候椭更,比如某個模塊不執(zhí)行哪审, 鎖競爭、CPU占用非常高等問題虑瀑, 又沒有足夠的log信息可以分析湿滓,那么可以查看stack trace信息,看看線程都被阻塞或者運行在那些代碼上舌狗,然后定位問題所在叽奥。

一、正常情況下輸出stacktrace
1.runtime/debug.PrintStack()打出當(dāng)前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打印出所有g(shù)oroutine的 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.通過系統(tǒng)信號

你可以使用runtime.Stack得到所有的goroutine的stack trace信息主届,事實上前面debug.PrintStack()也是通過這個方法獲得的赵哲。

為了更方便的隨時的得到應(yīng)用所有的goroutine的stack trace信息,我們可以監(jiān)聽SIGUSER1信號君丁,當(dāng)收到這個信號的時候就將stack trace打印出來枫夺。發(fā)送信號也很簡單,通過kill -SIGUSER1 <pid>就可以绘闷,不必?fù)?dān)心kill會將程序殺死橡庞,它只是發(fā)了一個信號而已较坛。

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代碼庫中的一段代碼,很簡單扒最,也很強大丑勤。

要注意的是,buf需要先指定大小吧趣,然后才能使用runtime.Stack(buf, true)法竞。然后就是第二個參數(shù)是個bool變量,如果為true是獲取所有g(shù)oroutine的stacktrace再菊,為false則是獲取當(dāng)前的。

現(xiàn)在看看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內(nèi)容輸出到log.Error里。

二泛豪、異常退出情況下輸出stacktrace
1.通過panic

如果應(yīng)用中有沒recover的panic,或者應(yīng)用在運行的時候出現(xiàn)運行時的異常稠诲,那么程序自動會將當(dāng)前的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方法,它在這一行調(diào)用m1方法价卤,m1方法在第13行調(diào)用m2方法劝萤,m2方法在第17行調(diào)用m3方法,m3方法在第21出現(xiàn)panic慎璧, 它們運行在goroutine 1中床嫌,當(dāng)前goroutine 1的狀態(tài)是running狀態(tài)。

如果想讓它把所有的goroutine信息都輸出出來胸私,可以設(shè)置 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的信息厌处,得到方法調(diào)用點的情況,同時這個信息將兩個goroutine的stack trace都打印出來了岁疼,而且goroutine 4的狀態(tài)是sleep狀態(tài)阔涉。

Go官方文檔對這個環(huán)境變量有介紹

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.

你可以設(shè)置 none、all捷绒、system瑰排、single、crash暖侨,歷史原因凶伙, 你可以設(shè)置數(shù)字0、1它碎、2函荣,分別代表none显押、all、system傻挂。

2.通過SIGQUIT信號

如果程序沒有發(fā)生panic,但是程序有問題乘碑,"假死“不工作,我們想看看哪兒出現(xiàn)了問題金拒,可以給程序發(fā)送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资铡。

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
  • 序言:七十年代末,一起剝皮案震驚了整個濱河市幢码,隨后出現(xiàn)的幾起案子笤休,更是在濱河造成了極大的恐慌,老刑警劉巖症副,帶你破解...
    沈念sama閱讀 219,490評論 6 508
  • 序言:濱河連續(xù)發(fā)生了三起死亡事件店雅,死亡現(xiàn)場離奇詭異,居然都是意外死亡贞铣,警方通過查閱死者的電腦和手機闹啦,發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 93,581評論 3 395
  • 文/潘曉璐 我一進店門,熙熙樓的掌柜王于貴愁眉苦臉地迎上來辕坝,“玉大人窍奋,你說我怎么就攤上這事〗闯” “怎么了费变?”我有些...
    開封第一講書人閱讀 165,830評論 0 356
  • 文/不壞的土叔 我叫張陵,是天一觀的道長圣贸。 經(jīng)常有香客問我挚歧,道長,這世上最難降的妖魔是什么吁峻? 我笑而不...
    開封第一講書人閱讀 58,957評論 1 295
  • 正文 為了忘掉前任滑负,我火速辦了婚禮,結(jié)果婚禮上用含,老公的妹妹穿的比我還像新娘矮慕。我一直安慰自己,他們只是感情好啄骇,可當(dāng)我...
    茶點故事閱讀 67,974評論 6 393
  • 文/花漫 我一把揭開白布痴鳄。 她就那樣靜靜地躺著,像睡著了一般缸夹。 火紅的嫁衣襯著肌膚如雪痪寻。 梳的紋絲不亂的頭發(fā)上螺句,一...
    開封第一講書人閱讀 51,754評論 1 307
  • 那天,我揣著相機與錄音橡类,去河邊找鬼蛇尚。 笑死,一個胖子當(dāng)著我的面吹牛顾画,可吹牛的內(nèi)容都是我干的取劫。 我是一名探鬼主播,決...
    沈念sama閱讀 40,464評論 3 420
  • 文/蒼蘭香墨 我猛地睜開眼研侣,長吁一口氣:“原來是場噩夢啊……” “哼谱邪!你這毒婦竟也來了?” 一聲冷哼從身側(cè)響起庶诡,我...
    開封第一講書人閱讀 39,357評論 0 276
  • 序言:老撾萬榮一對情侶失蹤惦银,失蹤者是張志新(化名)和其女友劉穎,沒想到半個月后灌砖,有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體璧函,經(jīng)...
    沈念sama閱讀 45,847評論 1 317
  • 正文 獨居荒郊野嶺守林人離奇死亡雄坪,尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點故事閱讀 37,995評論 3 338
  • 正文 我和宋清朗相戀三年振诬,在試婚紗的時候發(fā)現(xiàn)自己被綠了分歇。 大學(xué)時的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片。...
    茶點故事閱讀 40,137評論 1 351
  • 序言:一個原本活蹦亂跳的男人離奇死亡撩幽,死狀恐怖,靈堂內(nèi)的尸體忽然破棺而出箩艺,到底是詐尸還是另有隱情窜醉,我是刑警寧澤,帶...
    沈念sama閱讀 35,819評論 5 346
  • 正文 年R本政府宣布艺谆,位于F島的核電站榨惰,受9級特大地震影響,放射性物質(zhì)發(fā)生泄漏静汤。R本人自食惡果不足惜琅催,卻給世界環(huán)境...
    茶點故事閱讀 41,482評論 3 331
  • 文/蒙蒙 一、第九天 我趴在偏房一處隱蔽的房頂上張望虫给。 院中可真熱鬧藤抡,春花似錦、人聲如沸抹估。這莊子的主人今日做“春日...
    開封第一講書人閱讀 32,023評論 0 22
  • 文/蒼蘭香墨 我抬頭看了看天上的太陽药蜻。三九已至瓷式,卻和暖如春替饿,著一層夾襖步出監(jiān)牢的瞬間,已是汗流浹背蒿往。 一陣腳步聲響...
    開封第一講書人閱讀 33,149評論 1 272
  • 我被黑心中介騙來泰國打工盛垦, 沒想到剛下飛機就差點兒被人妖公主榨干…… 1. 我叫王不留,地道東北人瓤漏。 一個月前我還...
    沈念sama閱讀 48,409評論 3 373
  • 正文 我出身青樓腾夯,卻偏偏與公主長得像,于是被迫代替她去往敵國和親蔬充。 傳聞我的和親對象是個殘疾皇子蝶俱,可洞房花燭夜當(dāng)晚...
    茶點故事閱讀 45,086評論 2 355

推薦閱讀更多精彩內(nèi)容