go语言打印日期_实战分析一个运行起来会卡死的Go程序

序言

最近一位非常热心的网友建议结合demo来分析一下goroutine的调度器，而且还提供了一个demo代码，于是便有了本文，在此对这位网友表示衷心的感谢！

这位网友提供的demo程序可能有的gopher以前见过，已经知道了具体原因，但本文假定我们是第一次遇到这种问题，然后从零开始，通过一步一步的分析和定位，最终找到问题的根源及解决方案。

虽然本文不需要太多的背景知识，但最好使用过gdb或delve调试工具，了解汇编语言及函数调用栈当然就更好了。

本文我们需要重点了解下面这3个内容。

1. 调试工具无法准确显示函数调用栈时如何找到函数调用链；
2. 发生GC时，如何STOP THE WORLD；
3. 什么时候抢占调度不会起作用以及如何规避。

本文的实验环境为AMD64 Linux + go1.12

Demo程序及运行现象

package 

编译并运行，结果：

4 cores.
main is running, 

程序运行起来打印了这几条信息之后就再也没有输出任何信息，看起来程序好像卡死了！

我们第一次遇到这种问题，该如何着手开始分析呢？

分析代码

首先来分析一下代码，这个程序启动之后将会在main函数中创建一个worker goroutine和一个deadloop goroutine，加上main goroutine，一共应该有3个用户goroutine，其中

1. dealloop goroutine一直在执行一个死循环，并未做任何实际的工作；
2. worker goroutine每隔一秒循环打印worker is running；
3. main goroutine也一直在执行着一个循环，每隔一秒打印一下main is running，同时输出变量i的值并对i执行减减操作，当i等于0的时候会去调用runtime.GC函数触发垃圾回收。

因为我们目前掌握的知识有限，所以暂时看不出有啥问题，看起来一切都应该很正常才对，为什么会卡死呢？

分析日志

看不出程序有什么问题，我们就只能再来仔细看一下输出的日志信息。从日志信息可以看出，一开始main goroutine和worker 还很正常，但当打印了i = 1之后，main goroutine就再也没有输出信息了，而这之后worker也只打印了一次就没有再打印信息了。

从代码可以知道，打印了i = 1之后i就自减了1变成了0，i等于0之后就会去执行runtime.GC()，所以我们有理由怀疑卡死跟GC垃圾回收有关，怀疑归怀疑，我们需要拿出证据来证明它们确实有关才行。怎么找证据呢？

跟踪函数调用链

因为程序并没有退出，而是卡起了，我们会很自然的想到通过调试工具来看一下到底发生了什么事情。这里我们使用delve这个专门为Go程序定制的调试器。

使用pidof命令找到deadlock的进程ID，然后使用dlv attach上去，并通过goroutines命令查看程序中的goroutine

2369
bobo@ubuntu:~/study/go$ sudo dlv attach 

从输出信息可以看到程序中一共有14个goroutine，其它的goroutine不用管，我们只关心那3个用户goroutine，容易看出它们分别是

(0x416ab8

因为我们怀疑卡死跟runtime.GC()函数调用有关，所以我们切换到Goroutine 1并使用backtrace命令(简写bt)查看一下main goroutine的函数调用栈：

(dlv

从输出可以看到main goroutine的函数调用链为：

main

我们从main函数开始顺着这个链去看一下源代码，会发现mgc.go的1284行代码并非systemstack_switch函数，而是systemstack(stopTheWorldWithSema)这一句代码，在这里，这句代码的意思是从main goroutine的栈切换到g0栈并执行stopTheWorldWithSema函数，但从上面的函数调用栈并未看到stopTheWorldWithSema函数的身影，这可能是因为从main goroutine的栈切换到了g0栈导致调试工具没有处理好？不管怎么样，我们需要找到从stopTheWorldWithSema函数到runtime.futex函数的调用路径才能搞清楚到底发生了什么事情。

手动追踪函数调用链

既然调试工具显示的函数调用路径有问题，我们就需要手动来找到它，首先反汇编看一下当前正要运行的指令：

(dlv) disass
TEXTruntime.futex(SB) /usr/local/go/src/runtime/sys_linux_amd64.s
        mov    rdi, qword ptr [rsp+0x8]
        mov    esi, dword ptr [rsp+0x10]
        mov    edx, dword ptr [rsp+0x14]
        mov    r10, qword ptr [rsp+0x18]
        mov    r8, qword ptr [rsp+0x20]
        mov    r9d, dword ptr [rsp+0x28]
        mov    eax, 0xca
        syscall
=>    mov    dword ptr [rsp+0x30], eax
        ret

反汇编结果告诉我们，下一条即将执行的指令是sys_linux_amd64.s文件中的futex函数的倒数第二条指令：

==> mov    dword ptr [rsp+0x30], eax

为了搞清楚谁调用了futex函数，我们需要让futex执行完并返回到调用它的函数中去，多次使用si单步执行命令，程序返回到了runtime.futexsleep函数，如下：

(dlv) si
> runtime.futex() /usr/local/go/src/runtime/sys_linux_amd64.s:536 
      MOVQ    ts+16(FP), R10
      MOVQ    addr2+24(FP), R8
      MOVL    val3+32(FP), R9
      MOVL    $SYS_futex, AX
      SYSCALL
=>  MOVL     AX, ret+40(FP)
      RET
(dlv) si
> runtime.futex() /usr/local/go/src/runtime/sys_linux_amd64.s:537 
      MOVQ    addr2+24(FP), R8
      MOVL     val3+32(FP), R9
      MOVL     $SYS_futex, AX
      SYSCALL
      MOVL     AX, ret+40(FP)
=>  RET
(dlv) si
> runtime.futexsleep() /usr/local/go/src/runtime/os_linux.go:64 
          } else {
              ts.tv_nsec = 0
              ts.set_sec(int64(timediv(ns, 1000000000, (*int32)(unsafe.Pointer(&ts.tv_nsec)))))
          }
          futex(unsafe.Pointer(addr), _FUTEX_WAIT_PRIVATE, val, unsafe.Pointer(&ts), nil, 0)
=>  }
  
      // If any procs are sleeping on addr, wake up at most cnt.
      //go:nosplit
      func futexwakeup(addr *uint32, cnt uint32) {
           ret := futex(unsafe.Pointer(addr), _FUTEX_WAKE_PRIVATE, cnt, nil, nil, 0)
(dlv) 

现在程序停在了os_linux.go的64行(=>这个符号表示程序当前停在这里)，这是futexsleep函数的最后一行，使用n命令单步执行一行go代码，从runteme.futexsleep函数返回到了runtime.notetsleep_internal函数：

(

在runtime.notetsleep_internal函数中再连续使用几次n命令，函数从runtime.notetsleep_internal返回到了runtime.notetsleep函数：

(

为了搞清楚谁调用了notetsleep函数，继续执行几次n，奇怪的事情发生了，居然无法从notetsleep函数返回到调用它的函数中去，一直在notetsleep这个函数打转，好像发生了递归调用一样，见下：

(

notetsleep函数只有简单的几行代码，并没有递归调用，这真有点诡异，看来这个调试器还真有点问题。我们反汇编来看一下：

(dlv) disass
TEXT runtime.notetsleep(SB) /usr/local/go/src/runtime/lock_futex.go
=>    mov  rcx, qword ptr fs:[0xfffffff8]
        cmp  rsp, qword ptr [rcx+0x10]
        jbe    0x4095df
        sub   rsp, 0x20
        mov  qwordptr[rsp+0x18], rbp
        lea    rbp, ptr [rsp+0x18]
        mov  rax, qword ptr fs:[0xfffffff8]
        ......

现在程序停在notetsleep函数的第一条指令。我们知道，只要发生了函数调用，这个时候CPU的rsp寄存器一定指向这个函数执行完成之后的返回地址，所以我们看一下rsp寄存器的值

(

得到rsp寄存器的值之后我们来看一下它所指的内存单元中存放的是什么：

(

如果这个4374697是返回地址，那一定可以在这个地方下一个执行断点，试一试看：

(

真是苍天不负有心人，终于找到了stopTheWorldWithSema()函数，断点告诉我们runtime/proc.go文件的1050行调用了notetsleep函数，我们打开源代码可以看到这个地方确实是在一个循环中调用notetsleep函数。

到此，我们得到了main goroutine完整的函数调用路径：

main

分析stopTheWorldWithSema函数

接着，我们来仔细的看一下stopTheWorldWithSema函数为什么会调用notetsleep函数进入睡眠：

runtime/proc.go : 1048

// stopTheWorldWithSema is the core implementation of stopTheWorld.

stopTheWorldWithSema函数流程比较清晰：

1. 通过preemptall() 函数对那些正在运行go代码的goroutine设置抢占标记；
2. 停掉当前工作线程所绑定的p；
3. 通过cas操作修改那些处于系统调用之中的p的状态为_Pgcstop从而停掉对应的p；
4. 修改idle队列中p的状态为_Pgcstop;
5. 等待处于运行之中的p停下来。

从这个流程可以看出，stopTheWorldWithSema函数主要通过两种方式来Stop The World：

1. 对于那些此时此刻并未运行go代码的p，包括位于空闲队列之中的p以及处于系统调用之中的p，通过直接设置其状态为_Pgcstop来阻止工作线程绑定它们，从而保持内存引用的一致性。因为工作线程要执行go代码就必须要绑定p，没有p工作线程就无法运行go代码，不运行go代码也就无法修改内存之间的引用关系；
2. 对于那些此时此刻绑定到某个工作线程正在运行go代码的p，不能简单的修改其状态，只能通过设置抢占标记来请求它们停下来；

从前面的分析我们已经知道，deadlock程序卡在了下面这个for循环之中：

for 

程序一直在执行上面这个for循环，在这个循环之中，代码通过反复调用preemptall()来对那些正在运行的goroutine设置抢占标记然后通过notetsleep函数来等待这些goroutine的暂停。从程序的运行现象及我们的分析来看，应该是有goroutine没有暂停下来导致了这里的for循环无法break出去。

寻找没有暂停下来的goroutine

再次看一下我们的3个用户goroutine：

(0x416ab8

Goroutine 1所在的工作线程正在执行上面的for循环，所以不可能是它没有停下来，再来看Goroutine 5：

(dlv

从函数调用栈可以看出来goroutine 5已经停在了gopark处，所以应该是goroutine 6没有停下来，我们切换到goroutine 6看看它的函数调用栈以及正在执行的指令：

(

可以看出来goroutine一直在这里执行jmp指令跳转到自己所在的位置。为了搞清楚它为什么停不下来，我们需要看一下preemptall() 函数到底是怎么请求goroutine暂停的。

// Tell all goroutines that they have been preempted and they should stop.

继续看preemptone函数：

// Tell the goroutine running on processor P to stop.

从preemptone函数可以看出，所谓的抢占仅仅是给正在运行的goroutine设置一个标志而已，并没有使用什么有效的手段强制其停下来，所以被请求的goroutine应该需要去检查preempt和stackguard0这两个标记。但从上面deallock函数的汇编代码看起来它并没有去检查这两个标记，它只有一条跳转到自身执行死循环的指令，所以它应该是无法处理暂停请求的，也就没法停下来，因而这才导致了上面那个等待它停下来的for循环一直无法退出，最终导致整个程序像是卡死了一样的现象。

到此，我们已经过找到程序假死的表面原因是，因为执行deadlock函数的goroutine没有暂停导致垃圾回收无法进行，从而导致其它已经暂停了的goroutine无法恢复运行。但为什么其它goroutine可以暂停下来呢，唯独这个goroutine不行，我们需要继续分析。

探索真相

从上面的分析我们得知，preemptone函数通过设置

gp

来请求正在运行的goroutine暂停。为了找到哪里的代码会去检查这些标志，我们使用文本搜索工具在源代码中查找“preempt”、“stackPreempt”以及“stackguard0”这3个字符串，可以找到处理抢占请求的函数为newstack()，在该函数中如果发现自己被抢占，则会暂停当前goroutine的执行。然后再查找哪些函数会调用newstack函数，顺藤摸瓜便可以找到相关的函数调用链为

morestack_noctxt

从源代码中morestack函数的注释可以知道，该函数会被编译器插入到函数的序言(prologue)或尾声(epilogue)。

// Called during function prolog when more stack is needed.
//
// The traceback routines see morestack on a g0 as being
// the top of a stack (for example, morestack calling newstack
// calling the scheduler calling newm calling gc), so we must
// record an argument size. For that purpose, it has no arguments.
TEXT runtime·morestack(SB),NOSPLIT,$0-0

为了验证这个注释，我们反汇编一下main函数看看：

TEXTmain.main(SB) /home/bobo/study/go/deadlock.go
   0x0000000000489030<+0>:     mov   %fs:0xfffffffffffffff8,%rcx
   0x0000000000489039<+9>:     cmp   0x10(%rcx),%rsp
   0x000000000048903d<+13>:    jbe     0x4891b0 <main.main+384>
   0x0000000000489043<+19>:    sub    $0x80,%rsp
   0x000000000048904a<+26>:    mov   %rbp,0x78(%rsp)
   0x000000000048904f<+31>:     lea      0x78(%rsp),%rbp
   ......
   0x00000000004891a1<+369>:  callq    0x416a60 <runtime.GC>
   0x00000000004891a6<+374>:  mov    0x50(%rsp),%rax
   0x00000000004891ab<+379>:  jmpq   0x489108 <main.main+216>
   0x00000000004891b0<+384>:  callq   0x44f730 <runtime.morestack_noctxt>
   0x00000000004891b5<+389>:  jmpq   0x489030 <main.main>

在main函数的尾部我们看到了对runtime.morestack_noctxt函数的调用，往前我们可以看到，对runtime.morestack_noctxt的调用是通过main函数的第三条jbe指令跳转过来的。

0x000000000048903d<+13>:    jbe     0x4891b0 <main.main+384>
......
0x00000000004891b0<+384>:  callq   0x44f730 <runtime.morestack_noctxt>

jbe是条件跳转指令，它依靠上一条指令的执行结果来判断是否需要跳转。这里的上一条指令是main函数的第二条指令，为了看清楚这里到底在干什么，我们把main函数的前三条指令都列出来：

0x0000000000489030<+0>:    mov    %fs:0xfffffffffffffff8,%rcx  #main函数第一条指令
0x0000000000489039<+9>:    cmp    0x10(%rcx),%rsp        #main函数第二条指令
0x000000000048903d<+13>:   jbe     0x4891b0 <main.main+384>  #main函数第三条指令

在我写的Go语言调度器源代码情景分析系列文章中曾经介绍过，go语言使用fs寄存器实现系统线程的本地存储（TLS），main函数的第一条指令就是从TLS中读取当前正在运行的g的指针并放入rcx寄存器，第二条指令的源操作数是间接寻址，从内存中读取相对于g偏移16这个地址中的内容到rsp寄存器，我们来看看g偏移16的地址是放的什么东西，首先再来回顾一下g结构体的定义：

type 

可以看到结构体g的第一个成员stack占16个字节（lo和hi各占8字节），所以g结构体变量的起始位置加偏移16就应该对应到stackguard0字段。因此main函数的第二条指令相当于在比较栈顶寄存器rsp的值是否比stackguard0的值小，如果rsp的值更小，说明当前g的栈要用完了，有溢出风险，需要调用morestack_noctxt函数来扩栈，从前面的分析我们知道，preemptone函数在设置抢占标志时把需要被抢占的goroutine的stackguard0成员设置成了stackPreempt，而stackPreempt是一个很大的整数0xfffffffffffffade，对于goroutine来说其rsp栈顶不可能这么大。因此任何一个goroutine对应的g结构体对象的stackguard0成员一旦被设置为抢占标记，在进行函数调用时就会通过由编译器插入的指令去调用morestack_noctxt函数。

对于我们这个场景中的deadlock函数，它一直在执行jmp指令，并没有调用其它函数，所以它没有机会去检查g结构体对象的stackguard0成员，也就不会通过调用morestack_noctxt函数去执行处理抢占请求的newstack()函数（在该函数中如果发现自己被抢占，则会暂停当前goroutine的执行），当然也就停不下来了。

知道了问题的根源，要解决它就比较简单了，只需要在deadlock函数的for循环中调用一下其它函数应该就行了，读者可以自己去验证一下。不过需要提示一点的是，编译器并不会为每个函数都插入检查是否需要扩栈的代码，只有编译器觉得某个函数有栈溢出风险才会在函数开始和结尾处插入刚刚我们分析过的prologue和epilogue代码。

结论

从本文的分析我们可以看到，Go语言中的抢占调度其实是一种协作式抢占调度，它需要被抢占goroutine的配合才能顺利完成，而这种配合是通过编译器在函数的序言和尾声中插入的检测代码而实现的。这也提示我们，在编写go代码时需要避免纯计算式的长时间循环，这可能导致程序假死或STW时间过长。