golang的defer关键字特性奇遇

• 遇到问题

  20200313，我尝试分析并解决一个接口性能问题。这个接口是用golang实现的，大概的实现流程是：启动三个goroutine，分别用于获取不同的数据，等三份数据都齐备，再开启一个函数processData集中处理数据和逻辑。这里用到了sync.WaitGroup来做同步。

• 分析问题

  实际运行中，我发现接口的总体耗时比较高，于是在三个goroutine和processData函数内部直接用defer log.Printf这样的方式尝试输出函数的耗时（注：这里的耗时指的是，“函数结束的时间”与“接口刚开始执行的时间”的差值）。结果是，三个goroutine的日志打印的耗时都在50us以内，看到这个日志，我当时就认为是这三个goroutine的处理都很快。但是processData的日志打印的耗时为600ms，看起来是processData处理很耗时，再加日志后，发现processData并不慢。这时，我就怀疑是sync.WaitGroup的Wait操作很耗时，在网上多番查找，没有发现相关的信息。一时陷入了困难之中。
  过了30分钟，我还是没有想到解决办法。无奈之下，只能停下焦躁不安的心情，重新审视代码。重读代码过程中，回想起golang里延迟执行函数的实现原理：把defer后面的函数地址、参数压入栈，函数结束前执行这个栈的所有函数。

• 解决问题
  这里之所以有问题，是因为我把耗时作为参数直接传给了defer后面的函数，当运行到defer语句时，耗时就已经被计算出来并作为参数被压入栈，所以这里计算出来的耗时值是defer语句执行时的耗时，而不是整个函数的耗时。
  基于这个特性，我增加了一个打印耗时日志的函数，用于包裹log.Printf，并在这个函数里计算耗时，问题果然解决了。