背景

runtime.Caller能够拿到当前执行的文件名和行号，这个方法几乎所有的日志组件里都有使用。

但是问题也很明显，这个函数开销太大。跟了一下代码实现，发现主要就是不停地迭代，而这个迭代过程虽然单次消耗的时间可以忽略不计，但是对于日质量巨大的服务而言影响还是很大的。详情参见下面的代码go/src/runtime/symtab.go#L125

有生之年看见goto语句系列

各家的解决方案

网上了解了一下，目前没有找到不使用runtime包获取执行文件和行号的解决方案。既然官方的包很难有优化空间，那可以考虑一下业务侧有什么解决方案。于是查了一些github上比较知名的项目，学习了一下。

作为国内知名度最高的go-web框架，想必是有可取之处。话不多说上代码：github.com/beego/bee/cmd/commands/generate/generate.go#L91

记录文件名和行号的用法是这样的：

我们来看下utils.FILE()和utils.LINE()的实现：github.com/beego/bee/utils/utils.go#L252

在同一需求场景下，FILE和LINE分别调用了一次能耗较高的runtime.Caller，这个其实一次就行。可能作者出于功能单一性原则硬是分成两个函数分别获取，但是这并不是我们想要的。下一个

log （Google出品）

官方写的日志组件，在log包里的，值得参考一下: /usr/local/go/src/log/log.go#L149

注释里说明官方也是知道runtime.Caller性能有问题。这里的Logger里带有一个Mutex锁，方便在高并发或者多协程的时候保护上下文数据一致。

这里值得借鉴的是并没有所有的日志都记录文件名和行号，而是添加了标记位flag，只有在需要的业务场景下(Lshortfile或者Llongfile )，才调用runtime.Caller，避免不必要的开支。

另外一方面，在调用性能比较差的runtime.Caller之前，把锁释放，执行完毕后再把锁加上，继续处理自己后续的业务。这个可以避免锁的时间过长，影响其他业务。

zap （uber出品 5565星 https://github.com/uber-go/zap ）

敢以zap命名就可以看出官方的自信，从官方的benchmark数据来看，的确是算得上很快的：

Log a message and 10 fields:

| Package | Time | Objects Allocated |

| :--- | :---: | :---: |

| zap | 3131 ns/op | 5 allocs/op |

| zap (sugared) | 4173 ns/op | 21 allocs/op |

| zerolog | 16154 ns/op | 90 allocs/op |

| lion | 16341 ns/op | 111 allocs/op |

| go-kit | 17049 ns/op | 126 allocs/op |

| logrus | 23662 ns/op | 142 allocs/op |

| log15 | 36351 ns/op | 149 allocs/op |

| apex/log | 42530 ns/op | 126 allocs/op |

看一下实现行号和文件名的代码：go.uber.org/zap/logger.go#L284

它们将Caller信息放在CallerEntry.Entry.Caller结构里，并且和google类似，提供了标记位(addCaller)，只有在需要的场景下才会调用runtime.Caller.

值得一提的是，zap提供了Sugar和Desugar的模式，所谓Sugar就是提供程序员更友好方便的日志记录方式，但是牺牲了部分性能，核心就是Caller的skipCaller+2。Desugar就是个逆向的过程，可以将Sugared的结构再次回退到性能较高的原始模式，核心是Caller的callerSkip-2。两者可以在代码里面共同存在使用。

Sugar和Desuagr的实现：

log.With().Caller()

logrus (9017星，github同类最多星 https://github.com/sirupsen/logrus)

logrus作为GitHub上标星最多的golang日志组件，还是有必要研究一下的。

首先看下核心Logger的结构：github.com/logrus/logger.go#L11

ReportCallerentryPool sync.Pool

值得一提的是这里的Hooks,用于特殊日志出现时执行相应的动作。于是我想到，在设计日志组件的时候，是否可以将需要打印文件名和行号的日志作为特殊日志，为这类特殊日志添加hook，hook里才会去运行runtime.Calle

和上面几个组件不同的是，logrus使用的并不是runtime.Caller，而是获取runtime.Frame。 行号和文件名从Frame里获取: github.com/logrus/entry.go#L146

题外话：这里顺带也提一下刚刚看到的logrus的一个issue，个人感觉还是比较有意思的：https://github.com/sirupsen/logrus/issues/63

这个issue是2014年提出，讲的是当时logrus还不支持文件名和行号。而这个issue出现的时候，logrus已经有4年历史了。

不知道这是bug还是feature的程序员当时感觉世界都崩了，都4012年了，竟然还有不支持文件名和行号等stacktrace信息的日志组件。

作者当时也是出于性能考虑，特别谨慎对待这一特性，迟迟不肯加入这个功能，更是希望有需求的开发者，自己在Hook内实现。

lazy load?
想要StackTrace。自己加Hook去
谨慎的作者

还别说，那时候还真有人在Hook里实现了添加行号文件名，详情在这里： https://github.com/onrik/logrus

用法是这样的：

看到这些人早期都推荐用Hook，突然有种英雄所见略同的感觉，HIA~HIA~HIA~

精华

上面也参考了不少当下比较知名的框架或者日志组件。总结了以下几个可能是优化点的地方，当然本文并没有深入探讨性能数据，只是参考了各家的思路。

  1. 使用标识位。只有在需要用上行号和文件名的场景才改变标记位，然后调用runtime.Caller或者runtimr.Frame。
  2. 日志分级，或者logger实例分级(sugar&desugar)。不同级别的日志信息或者logger实例，拥有详细度不同的信息，性能也不一样。
  3. 使用资源池复用logger实例。
  4. 如果logger实例使用了mutex锁，那么在调用runtime.Caller或者runtimr.Frame之前先将锁释放，调用完毕后再锁上。
  5. 将一些不是普遍适用的逻辑，使用Hook的思想，由特殊事件勾起，减少不必要的开销。

参考