订阅造了个 Go 语言的日志轮子：golog
2018 11 22 11:13 PM 1646次查看
我总结了一下我的需求：
- 输出无结构的日志，方便人工读取。
- 可同时输出到屏幕和文件。
- 可输出日志的等级。
- 可输出日志所在的源文件和行号。
- 可订制日志样式。
- 支持日志轮转。
- 跨平台。
- 高性能。
既然要造轮子，就要从我最熟悉的 Python 库抄起，于是仿照 logging 库的设计，分成了
Logger - Handler - Writer 这三层的架构：type Logger struct {
level Level
handlers []*Handler
}
type Handler struct {
level Level
formatter *Formatter
writers []io.WriteCloser
}Level 就是日志等级了，没达到等级的日志会被 Logger 或 Handler 丢弃。Formatter 是用来格式化日志的。Writer 为了方便起见，就复用了 io.WriteCloser 接口。接着抄一个
LogRecord，用来记录一条日志的上下文：type Record struct {
level Level
time time.Time
file string
line int
message string
args []interface{}
}然后就可以实现
Formatter 了。为了能自定义日志样式，我将其拆成了一系列的 FormatPart：type Formatter struct {
formatParts []FormatPart
}
func (f *Formatter) Format(r *Record, buf *bytes.Buffer) {
for _, part := range f.formatParts {
part.Format(r, buf)
}
}
type FormatPart interface {
Format(r *Record, buf *bytes.Buffer)
}Formatter 只需要遍历它的 formatParts，依次调用它们的 Format() 方法即可完成整个格式化的过程。（实际上 Formatter 也实现了 Format() 方法，所以它也可以当成 FormatPart 使用。）然后解析样式字符串，就可以生成一系列
FormatPart 对象，最后将其组合成一个 Formatter 对象，就完成了整个解析过程。获取源码的文件路径和行号有个注意点：
_, file, line, _ := runtime.Caller(1)runtime.Caller 的参数是 1，表示只向上查 1 层调用者。如果封装了多层的话，这个参数就得增加。而这个函数非常慢，如果到了 4 的话，性能测试表明有将近一半的时间花在了这个函数上。所以不能在 SourceFormatPart 中去调用这个函数，而应该在第一层的入口函数中调用，将结果赋值给 Record 对象。接着就可以用
Formatter 来格式化 Record 了：func (h *Handler) Handle(r *Record) {
if r.level >= h.level {
buf := bufPool.Get().(*bytes.Buffer)
buf.Reset()
h.formatter.Format(r, buf)
content := buf.Bytes()
for _, w := range h.writers {
_, err := w.Write(content)
if err != nil {
logError(err)
}
}
bufPool.Put(buf)
}
}
const recordBufSize = 128
var bufPool = sync.Pool{
New: func() interface{} {
return bytes.NewBuffer(make([]byte, 0, recordBufSize))
},
}bytes.Buffer 对象，至少分配了 128 字节的内存，会存在很大的开销，所以我用 sync.Pool 重用了这些对象。现在就只剩
Writer 没有实现了，先把 stdout 和 stderr 加上：type ConsoleWriter struct {
*os.File
}
func NewConsoleWriter(f *os.File) *ConsoleWriter {
w := ConsoleWriter{
File: f,
}
return &w
}
func NewStdoutWriter() *ConsoleWriter {
return NewConsoleWriter(os.Stdout)
}
func NewStderrWriter() *ConsoleWriter {
return NewConsoleWriter(os.Stderr)
}
func (w *ConsoleWriter) Close() error {
w.File = nil
return nil
}*os.File 指针的结构体，而不是包含 io.Writer 接口，原因是这样的性能更快。我也没有直接用 type ConsoleWriter os.File 来定义一个新类型，因为这样我需要手动实现它的 Write() 方法，而这个方法需要将 *os.File 指针转换成 *ConsoleWriter 指针，我觉得 Go 语言的编译器实现这个极简单的方法也是有运行时开销的。接着就可以实现一个
FileWriter 了：const (
fileFlag = os.O_WRONLY | os.O_CREATE | os.O_APPEND
fileMode = 0644
)
func NewFileWriter(path string) (*os.File, error) {
return os.OpenFile(path, fileFlag, fileMode)
}os.File 在 Write() 时本来就加了锁，所以不用担心多线程环境下出错。如果一次性写入的字节数较少的话，对绝大部分的操作系统和文件系统而言，syscall.Write() 在多进程环境下也是原子的。不过依赖这个特性的话会丧失可移植性，严谨地支持多进程又会极大地影响性能，所以只支持多线程就行了。话说回来，这样实现的
FileWriter 性能很差，因为每次写入都直接对应一次系统调用。解决办法就是改为带缓冲区的版本：type BufferedFileWriter struct {
writer *os.File
buffer *bufio.Writer
locker sync.Mutex
updated bool
updateChan chan struct{}
stopChan chan struct{}
}
func NewBufferedFileWriter(path string) (*BufferedFileWriter, error) {
f, err := os.OpenFile(path, fileFlag, fileMode)
if err != nil {
return nil, err
}
w := &BufferedFileWriter{
writer: f,
buffer: bufio.NewWriterSize(f, bufferSize),
updateChan: make(chan struct{}, 1),
stopChan: make(chan struct{}),
}
go w.schedule()
return w, nil
}
func (w *BufferedFileWriter) schedule() {
locker := &w.locker
timer := time.NewTimer(0)
for {
select {
case <-w.updateChan:
stopTimer(timer)
timer.Reset(flushDuration)
case <-w.stopChan:
stopTimer(timer)
return
}
select {
case <-timer.C:
locker.Lock()
var err error
if w.writer != nil { // not closed
w.updated = false
err = w.buffer.Flush()
}
locker.Unlock()
if err != nil {
logError(err)
}
case <-w.stopChan:
stopTimer(timer)
return
}
}
}
func (w *BufferedFileWriter) Write(p []byte) (n int, err error) {
w.locker.Lock()
n, err = w.buffer.Write(p)
if !w.updated && n > 0 && w.buffer.Buffered() > 0 {
w.updated = true
w.updateChan <- struct{}{}
}
w.locker.Unlock()
return
}
func (w *BufferedFileWriter) Close() error {
w.locker.Lock()
err := w.buffer.Flush()
w.buffer = nil
if err == nil {
err = w.writer.Close()
} else {
e := w.writer.Close()
if e != nil {
logError(e)
}
}
w.writer = nil
w.locker.Unlock()
close(w.stopChan)
return err
}
func stopTimer(timer *time.Timer) {
if !timer.Stop() {
select {
case <-timer.C:
default:
}
}
}bufio.Writer 封装一下 os.File，这样写入时就会写到缓冲区里，达到容量上限时才会被刷新到文件中。但若只是这样而已，会导致日志量不大时，日志很久都不会被刷新到磁盘。于是我又增加了一个定时器，一旦有写入操作，就等待 100 毫秒，然后刷新缓冲区。绝大部分情况下，这个延迟是可以接受的。
至于拆分成两个
select 块，而不合并到一起，原因是可以少监听一个 channel，性能更好。其实最初我是想把写入的数据都通过 channel 传递到一个写线程，就不需要加锁了；后来发现 channel 内部也是用锁来实现的，性能反而比直接用锁更低，所以放弃了。顺带一提，
updateChan 带了个缓冲区，原因是 Write() 线程向它发送数据时并没有解锁，如果没有缓冲区就会阻塞在这；而接收线程也没法获取锁，就造成死锁了。stopChan 则不需要缓冲区，因为 close() 它是不会阻塞的。接着就可以实现轮转功能了：
type RotatingFileWriter struct {
BufferedFileWriter
path string
pos uint64
maxSize uint64
backupCount uint8
}
func NewRotatingFileWriter(path string, maxSize uint64, backupCount uint8) (*RotatingFileWriter, error) {
if maxSize == 0 {
return nil, errors.New("maxSize cannot be 0")
}
if backupCount == 0 {
return nil, errors.New("backupCount cannot be 0")
}
f, err := os.OpenFile(path, fileFlag, fileMode)
if err != nil {
return nil, err
}
stat, err := f.Stat()
if err != nil {
e := f.Close()
if e != nil {
logError(e)
}
return nil, err
}
w := RotatingFileWriter{
BufferedFileWriter: BufferedFileWriter{
writer: f,
buffer: bufio.NewWriterSize(f, bufferSize),
updateChan: make(chan struct{}, 1),
stopChan: make(chan struct{}),
},
path: path,
pos: uint64(stat.Size()),
maxSize: maxSize,
backupCount: backupCount,
}
go w.schedule()
return &w, nil
}
func (w *RotatingFileWriter) Write(p []byte) (n int, err error) {
length := uint64(len(p))
w.locker.Lock()
defer w.locker.Unlock()
if length >= w.maxSize {
err = w.rotate()
if err != nil {
return
}
n, err = w.buffer.Write(p)
if err != nil {
w.pos = uint64(n)
return
}
err = w.rotate()
} else {
pos := w.pos + length
if pos > w.maxSize {
err = w.rotate()
if err != nil {
return
}
}
n, err = w.buffer.Write(p)
if n > 0 {
w.pos += uint64(n)
if !w.updated && w.buffer.Buffered() > 0 {
w.updated = true
w.updateChan <- struct{}{}
}
}
}
return
}
func (w *RotatingFileWriter) rotate() error {
if w.writer == nil { // was closed
return os.ErrClosed
}
err := w.buffer.Flush()
if err != nil {
return err
}
err = w.writer.Close()
w.pos = 0
if err != nil {
w.writer = nil
w.buffer = nil
return err
}
for i := w.backupCount; i > 1; i-- {
oldPath := fmt.Sprintf("%s.%d", w.path, i-1)
newPath := fmt.Sprintf("%s.%d", w.path, i)
os.Rename(oldPath, newPath) // ignore error
}
err = os.Rename(w.path, w.path+".1")
if err != nil {
w.writer = nil
w.buffer = nil
return err
}
f, err := os.OpenFile(w.path, fileFlag, fileMode)
if err != nil {
w.writer = nil
w.buffer = nil
return err
}
w.writer = f
w.buffer.Reset(f)
return nil
}BufferedFileWriter 的 schedule() 方法，它自己要做的只是记录下打开文件时的位置，并在写入时计算位置，达到 maxSize 就轮转。然后再来实现按时间轮转：
type TimedRotatingFileWriter struct {
BufferedFileWriter
pathPrefix string
rotateDuration RotateDuration
backupCount uint8
}
func (w *TimedRotatingFileWriter) schedule() {
locker := &w.locker
flushTimer := time.NewTimer(0)
duration := nextRotateDuration(w.rotateDuration)
rotateTimer := time.NewTimer(duration)
for {
updateLoop:
for {
select {
case <-w.updateChan:
stopTimer(flushTimer)
flushTimer.Reset(flushDuration)
break updateLoop
case <-rotateTimer.C:
err := w.rotate(rotateTimer)
if err != nil {
logError(err)
}
case <-w.stopChan:
stopTimer(flushTimer)
stopTimer(rotateTimer)
return
}
}
flushLoop:
for {
select {
case <-flushTimer.C:
locker.Lock()
var err error
if w.writer != nil { // not closed
w.updated = false
err = w.buffer.Flush()
}
locker.Unlock()
if err != nil {
logError(err)
}
break flushLoop
case <-rotateTimer.C:
err := w.rotate(rotateTimer)
if err != nil {
logError(err)
}
case <-w.stopChan:
stopTimer(flushTimer)
stopTimer(rotateTimer)
return
}
}
}
}
func (w *TimedRotatingFileWriter) rotate(timer *time.Timer) error {
w.locker.Lock()
if w.writer == nil { // was closed
w.locker.Unlock()
return os.ErrClosed
}
err := w.buffer.Flush()
if err != nil {
w.locker.Unlock()
return err
}
err = w.writer.Close()
if err != nil {
w.locker.Unlock()
return err
}
f, err := openTimedRotatingFile(w.pathPrefix, w.rotateDuration)
if err != nil {
w.buffer = nil
w.writer = nil
w.locker.Unlock()
return err
}
w.writer = f
w.buffer.Reset(f)
duration := nextRotateDuration(w.rotateDuration)
timer.Reset(duration)
w.locker.Unlock()
go w.purge()
return nil
}select 块，只是增加了是否到达轮转时间的判断。如果因为轮转而跳出 select 块，则继续留在 for 循环中。自此为止，主体部分就算实现了，但还缺了个非常重要的步骤：命名。
官方库已经把
log 这个好名字给占用了，Github 上还有一堆五花八门的名字，我思索半天决定叫 golog 了，还是个回文。但是如果仅此而已，我调用时就得写成
golog.Info() 了，这么长明显不符合我的风格。于是又建了个叫 golog/log 的子包，把主要的函数扔进去，就能写成 log.Info() 了，VS Code 里直接保存文件就能自动 import 完整包名了，完美！最后测一下性能，和号称最快的结构化日志库 zerolog 对比了一下，如果让它也输出格式化的时间和源码的话，耗时比我的实现多一倍。
剩下比较影响性能的部分主要有：
runtime.Caller()。fmt.Sprint()和fmt.Sprintf()。Time.Format()。time.Now()。strconv.Itoa()。- 大量生成
Record对象。
sync.Pool 来重用 Record 即可。详细的实现就不列出了，还是去 Github 看吧。改造完再一测，已经甩开 zerolog 两倍了。
向下滚动可载入更多评论，或者点这里禁止自动加载。