通过golang goroutine stack分析死锁问题

前言:

      碰到死锁是一个很让人糟心的事情 ! 更让人无语的事,在测试环境中压力测试了好久都是ok的, 一点毛病都没有。但一到线上的正式环境居然出现死锁了。 主要现象是 队列中的任务不再被消费了,也没有相关的日志输出。 通过我们业务stats接口是可以看到进程内的状态, 队列确实没人消费。

# xiaorui.cc

{
    "alert_queue": 0,
    "input_task_queue": 30000,  // 这个
    "notify_queue": 30000,      // 这个
    "pushing_queue": 0,
    "qps_boss": {
        "15m": 189,
        "1m": 2053,
        "5m": 541,
        "avg": 4112,
        "count": 226029
    },
    "qps_proxy": {
        "15m": 1,
        "1m": 22,
        "5m": 5,
        "avg": 34,
        "count": 1919
    },
    "reporting_queue": 30000,
    "saver_queue": 0,
    "timer_heap_len": 30854,
    ....
    ....
}

我们知道golang是pmg模型,可能出现goroutine在不同的线程上浮动。 这样很难通过传统的pstack和strace分析出问题。 在其他语言里,你可以使用strace追踪关于mutex锁的调用,或者用pstack看到调用栈的信息。 


     该文章后续仍在不断的更新修改中, 请移步到原文地址  http://xiaorui.cc/?p=5160

     好在,golang runtime工具集里其实提供了打印所有 goroutine调用栈的工具,但是直接用官方的方法略显麻烦。 我这边简单把golang输出打印goroutine stack的工具封装了一个模块,我们通过外部的kill信号来控制stack的文件输出。

代码已经扔到github里了,没几行代码,只是更加简单易用而已。  https://github.com/rfyiamcool/stack_dump 

     

分析解决问题

    通过下面的stack输出,我们看到有在等待拿锁,但是居然等了4分钟,那么这必然是死锁的逻辑了。  进而继续分析,下面这两个不同的模块都等了4分钟的锁,那么冲突的逻辑肯定是他们了。   通过代码显示死锁的原因是出现了 锁的重用,也就说,拿到了锁,但又去拿锁, golang的sync.mutex是不可重入的,所以死锁了 !

    解决方法? 别重入加锁,要么就直接加大锁的粒度。


dump_stack库的使用方法

其实这次主要是给大家分享下 如何通过golang goroutine stack来分析各种问题,不单单是死锁问题,大家可以举一反三来解决更多的bug,比如想知道当前协程在做什么?    这里简单说下 github.com/rfyiamcool/dump_stack 库的使用方法。

package main
//xiaorui.cc


import (
	"time"

	"github.com/rfyiamcool/dump_stack"
)

func main() {
	dumpStack.SetupStackTrap()
	// dumpStack.SetupStackTrap("stack.log")
	time.Sleep(100 * time.Second)
}


然后我们给该进程发送 -USR1 信号,这样就可以拿到所有协程的函数调用栈.   我们也可以使用awk来统计分析当前stack的调用top.

# xiaorui.cc

awk -F '[' '/goroutine \d*/{print "[" $2}' stack.log | sort | uniq -c | sort -k1nr | head -20

5030 [select]:
1910 [semacquire]:
 952 [IO wait]:
 198 [chan send]:
 11  [sleep]:
  3  [runnable]:
  2  [chan receive, 6 minutes]:
  2  [select, 6 minutes]:
  1  [chan receive]:
  1  [IO wait, 1 minutes]:
  1  [running]:
  1  [select, 6 minutes, locked to thread]:
  1  [syscall]:


总结:

      死锁是个让人郁闷问题,好在及时解决,发现问题到解决上线不到一个小时….   多亏了golang内置了这么多的优秀debug工具。 


大家觉得文章对你有些作用! 如果想赏钱,可以用微信扫描下面的二维码,感谢!
另外再次标注博客原地址  xiaorui.cc