Golang 优化之路——自己造一个日志轮子

写在前面

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安全么？fmt和println打印日志都打印到了哪里？有兴趣的可以留言一下一起讨论。

最后

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

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

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

我说的是这样：

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

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

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

---

参考文献

• 【1】《Go 语言实战》