Golang中panic和defer的字符串打印顺序

环境

Ubuntu 16.04
Goland 2018.1.1
go1.10.1 linux/amd64

题目

package main
import (
 "fmt"
)
func main(){
 defer_call()
}
func defer_call() {
 defer func() {
  fmt.Println("打印前")
 }()
 defer func() {
  fmt.Println("打印中")
 }()
 defer func() {
  fmt.Println("打印后")
 }()
 panic("触发异常")
}

问题

在终端下编译运行，没有出现乱序打印的情况，但在***Goland***下运行则很容易出现"触发异常"乱序打印的情况。

分析源码

fmt.Println() 源码

// src/fmt/print.go
func Println(a ...interface{}) (n int, err error) {
 return Fprintln(os.Stdout, a...)
}

在这里可以看出，fmt.Println()向stdout输出数据。

// src/fmt/print.go
func Fprintln(w io.Writer, a ...interface{}) (n int, err error) {
 p := newPrinter()
 p.doPrintln(a) // 对入参进行格式化操作，数组元素之间用空格隔开，并且在最后元素后面加上回车
 n, err = w.Write(p.buf) // 写入文件
 p.free()
 return
}

在***Fprintln()***中，***doPrintln()***对数组入参做了一些格式化的操作，之后就调用***Write()将数据写入***stdout.。***Write()***是一个接口，***file.Write()***实现了该接口。

// src/os/file.go
func (f *File) Write(b []byte) (n int, err error) {
 if err := f.checkValid("write"); err != nil {
  return 0, err
 }
 n, e := f.write(b) // f.write执行数据写入操作
 if n < 0 {
  n = 0
 }
 if n != len(b) {
  err = io.ErrShortWrite
 }
 epipecheck(f, e)
 if e != nil {
  err = f.wrapErr("write", e)
 }
 return n, err
}

***file.Write()***中调用***fd.write()***来写入数据。

// src/os/file_unix.go
func (fd *FD) Write(p []byte) (int, error) {
 if err := fd.writeLock(); err != nil {
  return 0, err
 }
 defer fd.writeUnlock()
 if err := fd.pd.prepareWrite(fd.isFile); err != nil {
  return 0, err
 }
 var nn int
 for {	//  循环调用系统调用write()，直到p中的数据全部输出
  max := len(p)
  if fd.IsStream && max-nn > maxRW {
   max = nn + maxRW
  }
  n, err := syscall.Write(fd.Sysfd, p[nn:max])
  if n > 0 {
   nn += n
  }
  if nn == len(p) {
   return nn, err
  }
  if err == syscall.EAGAIN && fd.pd.pollable() {
   if err = fd.pd.waitWrite(fd.isFile); err == nil {
    continue
   }
  }
  if err != nil {
   return nn, err
  }
  if n == 0 {
   return nn, io.ErrUnexpectedEOF
  }
 }
}

***fd.write()***反复执行系统调用***write()***，确保数据都输出。因此，***fmt.Fprintln()***直接向stdout输出数据，而不像C库那样对***stdout***做了缓冲。

panic() 源码

panic调用了gopanic()

  // src/runtime/panic.go
  func gopanic(e interface{}) {
   gp := getg() // getg()返回当前协程的 g 结构体指针，g 结构体描述 goroutine
  if gp.m.curg != gp {
   print("panic: ")
   printany(e)
   print("\n")
   throw("panic on system stack")
  }
   
   // 此处省略一段代码
   
   var p _panic
   p.arg = e
   p.link = gp._panic
   gp._panic = (*_panic)(noescape(unsafe.Pointer(&p)))
   atomic.Xadd(&runningPanicDefers, 1)
   for {
    d := gp._defer // 获取当前协程defer链表的头节点
    if d == nil {
     break // 当前协程的defer都被执行后，defer链表为空，此时退出for循环
    }
    // If defer was started by earlier panic or Goexit (and, since we're back here, that triggered a new panic),
    // take defer off list. The earlier panic or Goexit will not continue running.
    if d.started {   // 发生panic后，在defer中又遇到panic(),则会进入这个代码块
     if d._panic != nil {
      d._panic.aborted = true
     }
     d._panic = nil
     d.fn = nil
     gp._defer = d.link
     freedefer(d) // defer 已经被执行过，则释放这个defer，继续for循环。
     continue
    }
    // Mark defer as started, but keep on list, so that traceback
    // can find and update the defer's argument frame if stack growth
    // or a garbage collection happens before reflectcall starts executing d.fn.
    d.started = true
    // Record the panic that is running the defer.
    // If there is a new panic during the deferred call, that panic
    // will find d in the list and will mark d._panic (this panic) aborted.
    d._panic = (*_panic)(noescape(unsafe.Pointer(&p)))
    p.argp = unsafe.Pointer(getargp(0))
    reflectcall(nil, unsafe.Pointer(d.fn), deferArgs(d), uint32(d.siz), uint32(d.siz)) // 执行当前协程defer链表头的defer
    p.argp = nil
    // reflectcall did not panic. Remove d.
    if gp._defer != d {
     throw("bad defer entry in panic")
    }
    d._panic = nil
    d.fn = nil
    gp._defer = d.link // 从defer链中移除刚刚执行过的defer
    // trigger shrinkage to test stack copy. See stack_test.go:TestStackPanic
    //GC()
    pc := d.pc
    sp := unsafe.Pointer(d.sp) // must be pointer so it gets adjusted during stack copy
    freedefer(d) // 释放刚刚执行过的defer
    if p.recovered { // defer()中遇到recover后进入这个代码块
     atomic.Xadd(&runningPanicDefers, -1)
     gp._panic = p.link
     // Aborted panics are marked but remain on the g.panic list.
     // Remove them from the list.
     for gp._panic != nil && gp._panic.aborted {
      gp._panic = gp._panic.link
     }
     if gp._panic == nil { // must be done with signal
      gp.sig = 0
     }
     // Pass information about recovering frame to recovery.
     gp.sigcode0 = uintptr(sp)
     gp.sigcode1 = pc
     mcall(recovery)     // 跳转到recover()处，继续往下执行
     throw("recovery failed") // mcall should not return
    }
   }
   // ran out of deferred calls - old-school panic now
   // Because it is unsafe to call arbitrary user code after freezing
   // the world, we call preprintpanics to invoke all necessary Error
   // and String methods to prepare the panic strings before startpanic.
   preprintpanics(gp._panic)
   startpanic()
   // startpanic set panicking, which will block main from exiting,
   // so now OK to decrement runningPanicDefers.
   atomic.Xadd(&runningPanicDefers, -1)
   printpanics(gp._panic) // 输出panic信息
   dopanic(0) // should not return
   *(*int)(nil) = 0 // not reached
  }

***gopanic()遍历当前协程的***defer***链表，并执行***defer***节点的***defer()函数。遇到***recover，则通过***mcall(recovery)退出***panic，恢复到***recover***的地方继续执行。否则，遍历完当前协程的***defer***链表后抛出***panic。从执行顺序来说，当前协程的***defer***按照先进后出的顺序执行。

// src/runtime/panic.go
 func printpanics(p *_panic) {
  if p.link != nil {
   printpanics(p.link)
   print("\t")
  }
  print("panic: ") // print()是内建函数，向stderr输出数据
  printany(p.arg)
  if p.recovered {
   print(" [recovered]")
  }
  print("\n")
 }

执行***panic***信息输出的是***printpanics()***这个函数，该函数利用内建函数***print()***，向***stderr***输出数据。 乱序输出的原因可能跟输出设备有关，再来看看进程打开的文件。

进程打开的文件

查找***Goland***进程

root@ubuntu:~# ps -ef | grep goland
john 3936 3300 7 09:56 ? 00:21:04 /opt/GoLand-2018.1.1/jre64/bin/java -classpath /opt/GoLand-2018.1.1/lib/bootstrap.jar:/opt/GoLand-2018.1.1/lib/extensions.jar:/opt/GoLand-2018.1.1/lib/util.jar:/opt/GoLand-2018.1.1/lib/jdom.jar:/opt/GoLand-2018.1.1/lib/log4j.jar:/opt/GoLand-2018.1.1/lib/trove4j.jar:/opt/GoLand-2018.1.1/lib/jna.jar -Xms128m -Xmx750m -XX:ReservedCodeCacheSize=240m -XX:+UseConcMarkSweepGC -XX:SoftRefLRUPolicyMSPerMB=50 -ea -Dsun.io.useCanonCaches=false -Djava.net.preferIPv4Stack=true -XX:+HeapDumpOnOutOfMemoryError -XX:-OmitStackTraceInFastThrow -Dawt.useSystemAAFontSettings=lcd -Dsun.java2d.renderer=sun.java2d.marlin.MarlinRenderingEngine -XX:ErrorFile=/home/john/java_error_in_GOLAND_.log -XX:HeapDumpPath=/home/john/java_error_in_GOLAND.hprof -Didea.paths.selector=GoLand2018.1 -Djb.vmOptionsFile=/opt/GoLand-2018.1.1/bin/goland64.vmoptions -Didea.platform.prefix=GoLand com.intellij.idea.Main
root 10546 9916 0 14:35 pts/20 00:00:00 grep --color=auto goland

Goland***的进程号为***3936，查找执行代码的子进程

root@ubuntu:~# ps -ef | grep 3936
john 3936 3300 7 09:56 ? 00:21:04 /opt/GoLand-2018.1.1/jre64/bin/java -classpath /opt/GoLand-2018.1.1/lib/bootstrap.jar:/opt/GoLand-2018.1.1/lib/extensions.jar:/opt/GoLand-2018.1.1/lib/util.jar:/opt/GoLand-2018.1.1/lib/jdom.jar:/opt/GoLand-2018.1.1/lib/log4j.jar:/opt/GoLand-2018.1.1/lib/trove4j.jar:/opt/GoLand-2018.1.1/lib/jna.jar -Xms128m -Xmx750m -XX:ReservedCodeCacheSize=240m -XX:+UseConcMarkSweepGC -XX:SoftRefLRUPolicyMSPerMB=50 -ea -Dsun.io.useCanonCaches=false -Djava.net.preferIPv4Stack=true -XX:+HeapDumpOnOutOfMemoryError -XX:-OmitStackTraceInFastThrow -Dawt.useSystemAAFontSettings=lcd -Dsun.java2d.renderer=sun.java2d.marlin.MarlinRenderingEngine -XX:ErrorFile=/home/john/java_error_in_GOLAND_.log -XX:HeapDumpPath=/home/john/java_error_in_GOLAND.hprof -Didea.paths.selector=GoLand2018.1 -Djb.vmOptionsFile=/opt/GoLand-2018.1.1/bin/goland64.vmoptions -Didea.platform.prefix=GoLand com.intellij.idea.Main
john 4000 3936 0 09:56 ? 00:00:01 /opt/GoLand-2018.1.1/bin/fsnotifier64
john 10506 3936 0 14:32 ? 00:00:00 /tmp/___go_build_1_go
root 10548 9916 0 14:35 pts/20 00:00:00 grep --color=auto 3936
root@ubuntu:~#

执行代码的子进程的进程号为***10506***，

子进程打开的文件

root@ubuntu:~# lsof -p 10506
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
___go_bui 10506 john cwd DIR 8,1 4096 287011 /home/john/go/src/awesomeProject
___go_bui 10506 john rtd DIR 8,1 4096 2 /
___go_bui 10506 john txt REG 8,1 2012100 963938 /tmp/___go_build_1_go
___go_bui 10506 john 0r FIFO 0,12 0t0 99707 pipe
___go_bui 10506 john 1w FIFO 0,12 0t0 99708 pipe
___go_bui 10506 john 2w FIFO 0,12 0t0 99709 pipe

子进程***10506***的***stdout***, stderr 分别被重定向到不同的匿名管道。

Goland进程打开的文件。

root@ubuntu:~# lsof -p 3936 | grep pipe
java 3936 john 24w FIFO 0,12 0t0 99707 pipe
java 3936 john 27r FIFO 0,12 0t0 99708 pipe
java 3936 john 30r FIFO 0,12 0t0 99709 pipe
java 3936 john 116r FIFO 0,12 0t0 32676 pipe
java 3936 john 117w FIFO 0,12 0t0 32676 pipe
java 3936 john 141r FIFO 0,12 0t0 33833 pipe
java 3936 john 142w FIFO 0,12 0t0 33833 pipe
java 3936 john 144r FIFO 0,12 0t0 33834 pipe
java 3936 john 145w FIFO 0,12 0t0 33834 pipe
java 3936 john 229w FIFO 0,12 0t0 33629 pipe
java 3936 john 230r FIFO 0,12 0t0 33630 pipe
java 3936 john 232r FIFO 0,12 0t0 33631 pipe
root@ubuntu:~#

可以看出，子进程的***stdout***，stderr***分别被匿名管道重定向到了父进程的文件描述符***27, 30。

分析

Goland***在子进程中执行代码，子进程的***stdout，***stderr***分别被匿名管道重定向到***Goland***父进程。Goland***对子进程***stdout, stderr***的输出响应顺序不同，导致***Goland***中"触发异常"这段文字的打印顺序不固定。所以在***Goland***中出现随机打印的情况，是由***Goland***自身的环境导致。在终端中***stdout，***stderr***都指向同一个字符设备，所以“触发异常”最后输出。

重现

代码

package main
import (
 "os"
)
func main() {
 os.Stdout.WriteString("stdout打印A\n")
 os.Stdout.WriteString("stdout打印B\n")
 os.Stdout.WriteString("stdout打印C\n")
 os.Stderr.WriteString("stderr打印\n")
}

在***Goland***中运行，会概率出现乱序输出。

输出

stdout打印A
stderr打印
stdout打印B
stdout打印C
Process finished with exit code 0

重现出乱序的结果

结论

• ***fmt.Println()***直接向stdout输出数据，并没有像C库那样对stdout的输出做缓冲
• 从代码上来看，协程遇到***panic***时，遍历本协程的***defer***链表，并执行***defer***。在执行***defer***过程中，遇到***recover***则停止***panic***，返回***recover***处继续往下执行。如果没有遇到***recover***，遍历完本协程的***defer***链表后，向***stderr***抛出***panic***信息。从执行顺序上来看，实际上是按照先进后出的顺序执行***defer***。
• 终端为字符设备，按照代码执行的先后顺序输出信息，也就是碰到***panic***时，按先进后出顺序执行***defer***函数，最后输出***panic***信息，所以在终端中的输出顺序是固定的。
• 在***Goland***中运行代码时，其实是在子进程中执行代码。子进程的***stdout***，***stderr***分别通过管道重定向到***Goland***父进程。因此在***Goland***中，子进程的输出可能会出现乱序的情况，本质上是***Goland***自身进程处理逻辑的问题。