14 July 2017
据我观察,基本没有人在用 Golang 原生的 log 包写日志。今天就讲一下如何通过200行代码封装一个功能完善的日志包。

写在前面

Golang 的log包内容不多,说实话,直接用来做日志开发有些简易。主要是缺少一些功能:

  1. 按日志级别打印和控制日志;
  2. 日志文件自动分割;
  3. 异步打印日志。

按日志级别打印和控制日志

我们实现的日志模块将会支持4个级别:

const (
	LevelError = iota
	LevelWarning
	LevelInformational
	LevelDebug
)

定义一个日志结构体:

type Logger struct {
	level int
	l     *log.Logger
}

func (ll *Logger) Error(format string, v ...interface{}) {
	if LevelError > ll.level {
		return
	}
	msg := fmt.Sprintf("[E] "+format, v...)
	ll.l.Printf(msg)
}

这样就能实现日志级别控制输出,并且打印的时候追加一个标记,比如上面的例子,Error 级别就会追加[E]

这个实现已经可以了,但是还是有优化的空间。比如打印追加标记[E]的时候,用的是字符串加法。字符串加法会申请新的内存,对性能不是很优化。我们需要通过字符数组来优化。

但我不会这么去优化了。这个时候看一下 log 包的 API,可以发现原生包是支持设置前缀的:

func (l *Logger) SetPrefix(prefix string)

再去看一下具体的实现:

func (l *Logger) formatHeader(buf *[]byte, t time.Time, file string, line int) {
	*buf = append(*buf, l.prefix...)

原生包在写日志前缀的时候就用到了[]byte来提升性能。既然人家已经提供了,我们还是不要自己造了。那么问题来了,设置前缀是初始化的时候就要设置,打印的时候自动输出出来。一个log.Logger对象只能有一个前缀,而我们需要4种级别的前缀,这个如何打印?

type Logger struct {
	level int
	err   *log.Logger
	warn  *log.Logger
	info  *log.Logger
	debug *log.Logger
}

我们直接申请4个日志对象就能解决。为了保证所有级别都打印到同一个文件里面,初始化的时候设置成同一个io.Writer即可。

logger := new(LcLogger)

logger.err = log.New(w, "[E] ", flag)
logger.warn = log.New(w, "[W] ", flag)
logger.info = log.New(w, "[I] ", flag)
logger.debug = log.New(w, "[D] ", flag)

设置日志级别:

func (ll *Logger) SetLevel(l int) {
	ll.level = l
}

打印的时候根据日志级别控制输出。(讲一个我遇到的坑。之前有一次打印日志打太多了,磁盘都打满了,就寻思着把日志级别调高减少打印内容。把级别调成 Error 后发现还是没有效果,最后看了看代码发现出问题的日志打印的是 Error 级别。。。Error级别的日志要尽量少打。)

func (ll *Logger) Error(format string, v ...interface{}) {
	if LevelError > ll.level {
		return
	}
	ll.err.Printf(format, v...)
}

日志文件自动分割

日志文件需要自动分割。否则一个文件过大,清理磁盘的时候这个文件因为还是打印日志没办法清理。

日志分割我觉得简单的以大小分割就好。

那么日志分割功能如何接入咱们上面实现的日志模块呢?关键就在io.Writer

type Writer interface {
    Write(p []byte) (n int, err error)
}

Writer这个接口只有一个方法,如此简单。原生包默认打印日志会输出到os.Stderr里面,这是一个os.File类型的变量,它实现了Writer这个接口。

func (f *File) Write(b []byte) (n int, err error)

写日志的时候,log 包会自动调用Write方法。我们可以自己实现一个Writer,在Write的时候计算一下写入此行日志之后当前日志文件大小,如果超过设定的值,执行一次分割。按日子分割日志也是这个时候操作。

推荐用 gopkg.in/natefinch/lumberjack.v2 这个包来做日志分割,功能很强大。

jack := &lumberjack.Logger{
	Filename: lfn,
	MaxSize:  maxsize, // megabytes
}

使用也很简单,jack对象就是一个Writer了,可以直接复制给Logger使用。

日志的异步输出

协程池也整个包:github.com/ivpusic/grpool。协程池就不展开说了,有兴趣的可以看看这个包的实现。

日志的结构体再一次升级:

type Logger struct {
	level int
	err   *log.Logger
	warn  *log.Logger
	info  *log.Logger
	debug *log.Logger
	p     *grpool.Pool
}

初始化:

logger.p = grpool.NewPool(numWorkers, jobQueueLen)

日志输出:

func (ll *Logger) Error(format string, v ...interface{}) {
	if LevelError > ll.level {
		return
	}
	ll.p.JobQueue <- func() {
		ll.err.Printf(format, v...)
	}
}

日志行号

如果你一步一步按上面的做了,打印日志设置了Lshortfile,展示行号的花,你可能会发现这个时候打印出来的行号有问题。打印日志的时候用到了runtime里面的堆栈信息,因为我们封装了一层,所以打印的堆栈深度会发生变化。简单的说就是深了一层。

原生的日志包提供了func (l *Logger) Output(calldepth int, s string) error来控制日志堆栈深度输出,我们再次对代码进行调整。

type Logger struct {
	level int
	err   *log.Logger
	warn  *log.Logger
	info  *log.Logger
	debug *log.Logger
	p     *grpool.Pool
	depth int
}

func (ll *Logger) Error(format string, v ...interface{}) {
	if LevelError > ll.level {
		return
	}
	ll.p.JobQueue <- func() {
		ll.err.Output(ll.depth, fmt.Sprintf(format, v...))
	}
}

我们只封装了一层,所以深度设置成3就可以了。

线程安全

原生包打印日志是线程安全的:

func (l *Logger) Output(calldepth int, s string) error {
	now := time.Now() // get this early.
	var file string
	var line int
	l.mu.Lock() // 看到这里了么?
	defer l.mu.Unlock()
	if l.flag&(Lshortfile|Llongfile) != 0 {
		// release lock while getting caller info - it's expensive.
		l.mu.Unlock()
		var ok bool
		_, file, line, ok = runtime.Caller(calldepth)
		if !ok {
			file = "???"
			line = 0
		}
		l.mu.Lock()
	}
	l.buf = l.buf[:0]
	l.formatHeader(&l.buf, now, file, line)
	l.buf = append(l.buf, s...)
	if len(s) == 0 || s[len(s)-1] != '\n' {
		l.buf = append(l.buf, '\n')
	}
	_, err := l.out.Write(l.buf)
	return err
}

有它的保证,我们也不需要考虑线程安全的问题了。

那么问题来了,fmt包打印日志是线程安全的么?println安全么?fmtprintln打印日志都打印到了哪里?有兴趣的可以留言一下一起讨论。

最后

日志的打印会用到诸如fmt.Sprintf的东西,这个在实现的时候将会用到反射。反射会对性能有影响,但是不用反射的话代码过于恶心。

完整的代码放到了 GitHub 上面,地址

上面介绍的日志只是在针对输出到文件。如果你想输出有邮件、ElasticSearch等其它地方,不要在初始化的时候通过各种复杂配置参数来实现。

我说的是这样:

NewLogger("es", ...)
NewLogger("smtp", ...)

这样做的问题就是,我只能用你提供好的东西,如果想扩展只能修改日志包了。如果这个包是第三方的包,那让别人怎么扩展呢?而且这种实现也不是 Golang 的实现风格。

其实大家看看原生的这些包,很多都是通过接口串联起来的。原生的 log 包,你可以认为他提供的服务主要是流程方面的服务,拼接好要打印的内容,包括行号、时间等等,保证线程安全,然后调用Writer来打印。如果我们要把日志打印到 ES 里面,就实现一个ESWriter。这才是 Golang 风格的代码。


参考文献

  • 【1】《Go 语言实战》

原文链接:Golang 优化之路——自己造一个日志轮子,转载请注明来源!

EOF

欢迎加微信交流与吐槽



本站总访问量次; 本站访客数人次; 本文总阅读量次;