Zap为什么快?从源码来聊聊其优化方案

文章目录


zap作为uber开源的日志框架,真的是非常的强,在他的github主页他吊打了所有的其他主流日志库【手动狗头】。

本篇文章就一起聊聊zap为什么这么快!


zap提供了两种Logger:Loggger和SugaredLogger。SugaredLogger其实是在Logger上面进行一层封装。所以我们来捋一捋Logger的底层实现,步步为营分析其为什么这么快。

一条日志是如何输出的

在github把zap的代码扒下来后,进入logger.go,这算是logger最外层的方法了。我们就从这里入手开始分析。(所有级别日志的实现逻辑是相同的,区别在于传入的参数不同。所以以info级别为例)。

首先进来第一步就是一个check:

//InfoLevle为日志级别的常量,msg为传入的消息
if ce := log.check(InfoLevel, msg); ce != nil {
  ce.Write(fields...)
}

这个check里面暗藏玄机,包含了多处优化。首先check进来就是一个判断

//lvl 是我们需要打的日志级别,这里为Info
if lvl < zapcore.DPanicLevel && !log.core.Enabled(lvl) {
	return nil
}

这个判断的主要作用就是在遇到了我们不需要打印的日志直接返回,避免不必要的操作。比如我们的日志级别是Info,如果一个Debug级别的日志过来就会直接返回。

不过这里有一个点需要注意,就是一个日志即使低于我们想打的级别,但是他大于Error级别,zap框架也要求打印这个日志。具体的原因就是zap觉得你的日志都Error以上了,必须得打!这就叫做,有一种日志叫zap觉得你要打的日志。

我们继续。接下来zap会组装一个叫Entry的结构体,这个结构体包含最基本的信息:名称、日志级别、时间、用户要输出的日志信息。最基本信息。

接下来还会经历一个check,这个check会在刚才创建的Entry的基础上补充一些core的信息(日志的输出方式,例如文件、Es等等)。接下来看看是如何做的。

//这里的ce变量会传入一个nil
func (c *ioCore) Check(ent Entry, ce *CheckedEntry) *CheckedEntry {
	if c.Enabled(ent.Level) {
		return ce.AddCore(ent, c)
	}
	return ce
}

这个check同样会检查一次日志级别是否符合用户设置的需要打印的级别,如果不符合会直接返回空。这里第二次检查是为了保证在要打印的日志级别小于我们设置的级别,但是大于zap认为不能忽略的日志级别【DPanicLevel以上】的时候,不添加附加信息【不需要输出给用户】。接下来的重点是ce.AddCore(ent, c)这个方法。

func (ce *CheckedEntry) AddCore(ent Entry, core Core) *CheckedEntry {
  //上方我们传入的ce是nil
	if ce == nil {
		ce = getCheckedEntry()
		ce.Entry = ent
	}
	ce.cores = append(ce.cores, core)
	return ce
}

这里会判断ce是否为nil,如果为nil就调用getCheckedEntry()方法获取一个CheckedEntry,但是这个方法不是直接新建一个对象,而是从sync.Poll对象池中获取对象。

这样做的好处是可以避免多次创建对象,因为如果每一个日志都创建一个新对象,就会不断的创建对象,打日志又是一个高频的操作,不断的创建销毁对象是对GC是有一定压力的,就算GC做的再好也是会有STW的问题。所以对象复用也是zap的一个优化点。

获取了新的CheckedEntry之后,直接把基础的Entry放入其中即可。这里要提一句的是:CheckedEntry继承了Entry,所以直接赋值即可。

获取到了CheckEntry之后有这样一段代码:willWrite := ce != nil。这里的willWrite变量主要是想区分到底是用户想打日志还是zap觉得你要打日志【手动狗头】。

接下来的流程就是对zap想让你打日志的几个级别设置一下zap想让你程序做的事情。具体如下:

  • panic级别日志:写日志,然后触发一个panic
  • fatal级别日志:写日志,然后执行执行os.Exit(这里支持自定义操作)
  • dpainc级别日志:写日志,如果设置了zap处于development模式则触发一个painc

至此为止,无论是我们想打的日志,还是zap想让我们打的日志,CheckEntry都已经组装好了,这说明前置工作都做好了,可以进行打日志操作了。

接下来就是前方那个判断是不是你想打日志的标志起作用的时候了,在组装好CheckEntry后这里会判断一下,如果是zap想让你打的日志,就会直接返回,不会执行后续的操作了。代码如下:

if !willWrite {
  return ce
}

如果是用户需要打的日志,则需要根据实际的配置,来为CheckEntry增加一些信息,比如函数名、行号等等信息。具体代码如下:

ce.ErrorOutput = log.errorOutput
if log.addCaller {
  //获取栈帧
  frame, defined := getCallerFrame(log.callerSkip + callerSkipOffset)
  if !defined {
    //获取栈帧失败
    fmt.Fprintf(log.errorOutput, "%v Logger.check error: failed to get caller\n", ent.Time.UTC())
    log.errorOutput.Sync()
  }
	//增加调用栈信息
  ce.Entry.Caller = zapcore.EntryCaller{
    Defined:  defined,
    PC:       frame.PC,
    File:     frame.File,
    Line:     frame.Line,
    Function: frame.Function,
  }
}
if log.addStack.Enabled(ce.Entry.Level) {
  ce.Entry.Stack = StackSkip("", log.callerSkip+callerSkipOffset).String
}

增加完这些细节之后,check终于结束了。接下来就进入write阶段,也就是最开始看到的代码:

if ce := log.check(InfoLevel, msg); ce != nil {
  //现在到了这里
  ce.Write(fields...)
}

进入write之后首先有一个dirty的判断,这里主要是因为我们的CheckedEntry是从对象池里拿出来了,所以可能存在脏数据。具体操作很简单:

if ce.dirty {
  if ce.ErrorOutput != nil {
    fmt.Fprintf(ce.ErrorOutput, "%v Unsafe CheckedEntry re-use near Entry %+v.\n", ce.Time, ce.Entry)
    ce.ErrorOutput.Sync()
  }
  return
}
//dirty会在从对象池拿出来后进行reset时置false,如果为true则reset失败
ce.dirty = true

接下来就是开始写日志,但是这个写日志不一定是要写到文件中,可以写到es等等,只要我们注册一个core进zap就可以多一种日志输出方式。所以在写日志的时候要输出到用户指定的所有方式中。看起来很复杂,其实就是一个for循环遍历所有的core进行输出。

所以这里的core可以自己来实现,比如说异步写文件,比如说输出到数据库等等。

for i := range ce.cores {  err = multierr.Append(err, ce.cores[i].Write(ce.Entry, fields))}

日志写完了,我们就需要把从sync.Pool中拿出来的CheckedEntry再放回池子,以便复用。

最后的最后,别忘记了前面提到zap想让我们打的日志,这些日志zap规定在打完日志还需要发出一些panic或者调用os.Exit。代码如下:

switch should {  case WriteThenPanic:  	panic(msg)  case WriteThenFatal:  	exit.Exit()  case WriteThenGoexit:  	runtime.Goexit()}

至此一条日志输出完毕!


一条日志是如何落盘的

在zap中遍历所有的core调用coreWrite方法进行输出,这里可自定义很多的输出方式,输出到es、输出到数据库等等。这里就主要聊聊输出到文件的过程。

来到ioCore(文件操作)的Write方法,第一行就是对消息进行编码:

buf, err := c.enc.EncodeEntry(ent, fields)

进来第一行就是通过clone方法复制了所有信息,当然点进去看会发现仍然是用了对象池来进行对象复用减少GC。这里不仅从对象池拿了JsonEncoder,还从对象池拿了一个Buffer对象,这个Buffer对象是存储最后打印出的日志的Json串。

这里使用复制还有一个好处就是,一个新的对象可以避免在写日志的时候发生竞争,因为zap支持多种输出方式,如果有多个输出的时候很容易就发生竞争。所以这里的复制避免锁竞争也是一个优化点。

接下来就是组装Json串,组装Json串并没有调用系统Json库,而是以自己实现了一套字符串拼接(其实是以字符的byte进行拼接)的方式来进行组装。这样的好处是避免了通过比较慢的反射来组装Json串,同时byte拼接也比字符拼接更快。这里也是zap的一个优化点。

拼接的代码太过啰嗦,也很简单,就是一顿++++,为了阅读体验这里就不贴了。

拼接完后直接返回byte数组(要落盘的Json串的byte数组)。然后把前面从对象池取出来的对象再放回对象池以便复用。

接下来就很简单了,就是直接落盘。代码如下:

_, err = c.out.Write(buf.Bytes())buf.Free()

在落盘之后还有一个小操作:如果日志的级别大于Error,直接强制刷盘。代码如下:

if ent.Level > ErrorLevel {  c.Sync()}

这样做的目的是因为如果大于Error,zap可能会进行例如panicos.exit等操作(上文提到过)。如果不强制刷盘,可能会丢失数据。

至此日志落盘的流程全部结束。


小结

整篇文章在源码层面分析了zap快的原因,在这里稍做总结。

  1. 如果日志级别是小于用户配置的级别且小于zap认为必须打日志的级别,直接忽略,连对象都不生成。
  2. 利用sync.Poll对象池来复用对象减少GC。
  3. 在输出日志前先复制,避免多个输出进行锁竞争。
  4. 不使用反射获取Json串,而是以手动以byte方式拼接Json串,来提高效率。

以上就是本篇文章的全部内容,如果你觉得文章写得不错,求点赞,求转发。欢迎关注公众号(高压锅码农777)点击右下角联系作者,一起交流学习。

我是锅哥,祝你幸福,我们下期见。

上一篇:ThreadLocal源码


下一篇:强引用和弱引用的Threadlocal