Go猜想录
大道至简,悟者天成
标准库 log 源码分析

本分析基于 go 1.23 版本

简介

log 库是 go 官方提供一个简单的日志记录标准库,是由 Russ Cox 操刀编写的,并由 Joe Tsai 在后续版本做了对锁的优化,大幅度提高了运行效率。总代码 500 余行,核心代码 200 余行,实现的简洁优雅,很值得新手学习。

使用

package main

import (
	"bytes"
	"fmt"
	"log"
)

func main() {
	var (
		buf    bytes.Buffer
		logger = log.New(&buf, "[Prefix]", log.Lshortfile)
	)

	logger.Print("Hello!")

	// [Prefix]main.go:15: Hello!
	fmt.Print(&buf)
}

首先需要新建一个 logger,需要传入三个参数,日志输出位置(一个 io.Writer 对象)、日志前缀(字符串,每次打印日志都会跟随输出)、日志属性(定义好的常量)。创建好就可以调用方法进行日志输出。

日志属性可选项如下:

属性 说明
Ldate 当前时区的日期,格式:2009/01/23
Ltime 当前时区的时间,格式:01:23:23
Lmicroseconds 当前时区的时间,格式:01:23:23.123123,精确到微妙
Llongfile 全文件名和行号,格式:/a/b/c/d.go:23
Lshortfile 当前文件名和行号,格式:d.go:23,会覆盖 Llongfile
LUTC 使用 UTC 而非本地时区,推荐日志全部使用 UTC 时间
Lmsgprefix 将 prefix 内容从行首移动到日志内容前面
LstdFlags 标准 logger 对象的初始值(等于:Ldate|Ltime

这些属性都是预定义好的常量,可以直接通过 | 运算符组合使用。且这些属性的格式和顺序都无法更改,当 Llongfile 或者 Lshortfile 被设置时 header 中会多个冒号。

logger 结构体支持 9 种方法来输出日志内容:

函数名 作用 使用示例
Print 打印日志 log.Print(“Print”)
Printf 打印格式化日志 log.Printf(“Printf: %s”, “print”)
Println 打印日志并换行 log.Println(“Println”)
Panic 打印日志后执行 panic(s)(s 为日志内容) log.Panic(“Panic”)
Panicf 打印格式化日志后执行 panic(s) log.Panicf(“Panicf: %s”, “panic”)
Panicln 打印日志并换行后执行 panic(s) log.Panicln(“Panicln”)
Fatal 打印日志后执行 os.Exit(1) log.Fatal(“Fatal”)
Fatalf 打印格式化日志后执行 os.Exit(1) log.Fatalf(“Fatalf: %s”, “fatal”)
Fatalln 打印日志并换行后执行 os.Exit(1) log.Panicln(“Panicln”)

Panic 系列和 Fatal 系列主要的区别如下:

  • panic(s):用于处理不可恢复的错误或意外情况,会执行 defer 语句,允许通过 recover 恢复。适合在需要捕获并处理异常的情况下使用。
  • os.Exit(1):用于立即退出程序,不执行 defer 语句,也不能通过 recover 恢复。适合在程序需要立即终止时使用。

这些函数使用的时候不需要额外添加换行符,log 包会在检测到最后一个字符不是换行符时自动补充一个换行符。

源码分析

位的使用

const (
	Ldate = 1 << iota
	Ltime
	Lmicroseconds
	Llongfile
	Lshortfile
	LUTC
	Lmsgprefix
	LstdFlags = Ldate | Ltime
)

是如何只提供一个配置项 flags 就可以支持如此多的配置呢?秘密就在位的运算上,这个 int 的每一位都代表了一个不同的配置,通过简单的与运算就可以得知是否设置了该项配置。

if flag&Lmsgprefix == 0 {
	*buf = append(*buf, prefix...)
}

整型的 ASCII 编码

// Cheap integer to fixed-width decimal ASCII. Give a negative width to avoid zero-padding.
func itoa(buf *[]byte, i int, wid int) {
	// Assemble decimal in reverse order.
	var b [20]byte
	bp := len(b) - 1
	for i >= 10 || wid > 1 {
		wid--
		q := i / 10
		b[bp] = byte('0' + i - q*10)
		bp--
		i = q
	}
	// i < 10
	b[bp] = byte('0' + i)
	*buf = append(*buf, b[bp:]...)
}

这段代码实现了一个将整数转换为定宽(Fixed-width)的十进制ASCII字符串的函数,并将结果追加到一个字节切片中。 itoa 函数接受三个参数:

  1. buf *[]byte:指向一个字节切片的指针,用来存储转换后的结果。
  2. i int:要转换的整数。
  3. wid int:指定的宽度。如果为负数,表示不要进行零填充。 b 是一个长度为 20 的字节数组,用来临时存储转换过程中生成的字符。bp 是一个指针,初始化为数组 b 的最后一个位置,表示当前存放字符的位置。(在Go语言中,int 类型的长度通常与平台有关。在64位系统上,int 通常是64位的。这意味着最大值为 9223372036854775807(19位数字),最小值为 -9223372036854775808(负号加19位数字)。即使考虑到负号,20个字节足够容纳任何可能的整数值。)
    通过循环的计算,将传入的 i 值,转换成了 ASCII 值,同时保证了宽度是 wid。

atomic

type Logger struct {
	outMu sync.Mutex
	out   io.Writer // destination for output

	prefix    atomic.Pointer[string] // prefix on each line to identify the logger (but see Lmsgprefix)
	flag      atomic.Int32           // properties
	isDiscard atomic.Bool
}

在之前的版本中,对 Logger 结构体中的字段修改都需要获取锁(当时还没有这些 atomic 类型,只能用锁),在这里都优化成了使用 atomic 类型。只在写入日志时使用锁。

func TestAtomic(t *testing.T) {
	var flag atomic.Int32
	val := int32(1024)
	flag.Store(val)
	assert.Equal(t, val, flag.Load())

	var prefix atomic.Pointer[string]
	str := "p"
	prefix.Store(&str)
	assert.Equal(t, str, *prefix.Load())
}

sync.Pool

var bufferPool = sync.Pool{New: func() any { return new([]byte) }}

func getBuffer() *[]byte {
	p := bufferPool.Get().(*[]byte)
	*p = (*p)[:0]
	return p
}

func putBuffer(p *[]byte) {
	if cap(*p) > 64<<10 {
		*p = nil
	}
	bufferPool.Put(p)
}
  • 通过复用指针,sync.Pool 可以更快地提供切片,而不需要每次都进行内存分配和回收。
  • 这有助于提高程序的性能,特别是在需要频繁创建和销毁字节切片的场景中。
  • 当分配的字节切片容量大于 64 KB 时就不回收了,直接释放

runtime.Caller

// Caller reports file and line number information about function invocations on
// the calling goroutine's stack. The argument skip is the number of stack frames
// to ascend, with 0 identifying the caller of Caller.  (For historical reasons the
// meaning of skip differs between Caller and [Callers].) The return values report the
// program counter, file name, and line number within the file of the corresponding
// call. The boolean ok is false if it was not possible to recover the information.
func Caller(skip int) (pc uintptr, file string, line int, ok bool) {
	rpc := make([]uintptr, 1)
	n := callers(skip+1, rpc[:])
	if n < 1 {
		return
	}
	frame, _ := CallersFrames(rpc).Next()
	return frame.PC, frame.File, frame.Line, frame.PC != 0
}
  • skipskip 参数指定了需要跳过的栈帧数量。skip=0 时,表示当前调用 runtime.Caller 的那一行代码,skip=1 表示调用者的调用者,以此类推。
  • pc:第一个返回值,表示程序计数器(PC)。
  • file:调用的源文件的文件名。
  • line:调用的源文件的行号。
  • ok:布尔值,表示是否成功获取信息。

PC(Program Counter)runtime.Caller 的第一个返回值是程序计数器,它是一个 uintptr 类型的值,表示调用者在代码中的位置。这个值可以传递给 runtime.FuncForPC 函数来获取与该程序计数器关联的函数信息,比如函数名、文件名和行号等。

func TestCaller(t *testing.T) {
	// Skip 0 means we're getting the Caller inside exampleFunction itself
	pc, file, line, ok := runtime.Caller(0)
	if !ok {
		fmt.Println("runtime.Caller failed")
		return
	}

	// Retrieve the function details using the program counter
	fn := runtime.FuncForPC(pc)
	functionName := fn.Name()

	t.Logf("Called from function: %s\n", functionName)
	t.Logf("In file: %s\n", file)
	t.Logf("At line: %d\n", line)
}

函数式编程(闭包)

func (l *Logger) Printf(format string, v ...any) {
	l.output(0, 2, func(b []byte) []byte {
		return fmt.Appendf(b, format, v...)
	})
}

是如何将生成的 header 放在输出的内容之前的,这里传入了一个 appendOutput func([]byte) []byte 类型的函数,在调用的时候将 header 传入即可,返回值就是生成好格式的结果。

Reference

附录

package log

import (
	"fmt"
	"io"
	"runtime"
	"sync"
	"sync/atomic"
	"time"
)

// These flags define which text to prefix to each log entry generated by the [Logger].
// Bits are or'ed together to control what's printed.
// With the exception of the Lmsgprefix flag, there is no
// control over the order they appear (the order listed here)
// or the format they present (as described in the comments).
// The prefix is followed by a colon only when Llongfile or Lshortfile
// is specified.
// For example, flags Ldate | Ltime (or LstdFlags) produce,
//
//	2009/01/23 01:23:23 message
//
// while flags Ldate | Ltime | Lmicroseconds | Llongfile produce,
//
//	2009/01/23 01:23:23.123123 /a/b/c/d.go:23: message
const (
	Ldate = 1 << iota
	Ltime
	Lmicroseconds
	Llongfile
	Lshortfile
	LUTC
	Lmsgprefix
	LstdFlags = Ldate | Ltime
)

// A Logger represents an active logging object that generates lines of
// output to an [io.Writer]. Each logging operation makes a single call to
// the Writer's Write method. A Logger can be used simultaneously from
// multiple goroutines; it guarantees to serialize access to the Writer.
type Logger struct {
	outMu sync.Mutex
	out   io.Writer // destination for output

	prefix    atomic.Pointer[string] // prefix on each line to identify the logger (but see Lmsgprefix)
	flag      atomic.Int32           // properties
	isDiscard atomic.Bool
}

// New creates a new [Logger]. The out variable sets the
// destination to which log data will be written.
// The prefix appears at the beginning of each generated log line, or
// after the log header if the [Lmsgprefix] flag is provided.
// The flag argument defines the logging properties.
func New(out io.Writer, prefix string, flag int) *Logger {
	l := new(Logger)
	l.SetOutput(out)
	l.SetPrefix(prefix)
	l.SetFlags(flag)
	return l
}

// SetOutput sets the output destination for the logger.
func (l *Logger) SetOutput(w io.Writer) {
	l.outMu.Lock()
	defer l.outMu.Unlock()
	l.out = w
	l.isDiscard.Store(w == io.Discard)
}

// SetPrefix sets the output prefix for the logger.
func (l *Logger) SetPrefix(prefix string) {
	l.prefix.Store(&prefix)
}

// SetFlags sets the output flags for the logger.
// The flag bits are [Ldate], [Ltime], and so on.
func (l *Logger) SetFlags(flag int) {
	l.flag.Store(int32(flag))
}

// Writer returns the output destination for the logger.
func (l *Logger) Writer() io.Writer {
	l.outMu.Lock()
	defer l.outMu.Unlock()
	return l.out
}

// Prefix returns the output prefix for the logger.
func (l *Logger) Prefix() string {
	if p := l.prefix.Load(); p != nil {
		return *p
	}
	return ""
}

// Flags returns the output flags for the logger.
// The flag bits are [Ldate], [Ltime], and so on.
func (l *Logger) Flags() int {
	return int(l.flag.Load())
}

// Cheap integer to fixed-width decimal ASCII. Give a negative width to avoid zero-padding.
func itoa(buf *[]byte, i int, wid int) {
	// Assemble decimal in reverse order.
	var b [20]byte
	bp := len(b) - 1
	for i >= 10 || wid > 1 {
		wid--
		q := i / 10
		b[bp] = byte('0' + i - q*10)
		bp--
		i = q
	}
	// i < 10
	b[bp] = byte('0' + i)
	*buf = append(*buf, b[bp:]...)
}

// formatHeader writes log header to buf in following order:
//   - l.prefix (if it's not blank and Lmsgprefix is unset),
//   - date and/or time (if corresponding flags are provided),
//   - file and line number (if corresponding flags are provided),
//   - l.prefix (if it's not blank and Lmsgprefix is set).
func formatHeader(buf *[]byte, t time.Time, prefix string, flag int, file string, line int) {
	if flag&Lmsgprefix == 0 {
		*buf = append(*buf, prefix...)
	}
	if flag&(Ldate|Ltime|Lmicroseconds) != 0 {
		if flag&LUTC != 0 {
			t = t.UTC()
		}
		if flag&Ldate != 0 {
			year, month, day := t.Date()
			itoa(buf, year, 4)
			*buf = append(*buf, '/')
			itoa(buf, int(month), 2)
			*buf = append(*buf, '/')
			itoa(buf, day, 2)
			*buf = append(*buf, ' ')
		}
		if flag&(Ltime|Lmicroseconds) != 0 {
			hour, min, sec := t.Clock()
			itoa(buf, hour, 2)
			*buf = append(*buf, ':')
			itoa(buf, min, 2)
			*buf = append(*buf, ':')
			itoa(buf, sec, 2)
			if flag&Lmicroseconds != 0 {
				*buf = append(*buf, '.')
				itoa(buf, t.Nanosecond()/1e3, 6)
			}
			*buf = append(*buf, ' ')
		}
	}
	if flag&(Lshortfile|Llongfile) != 0 {
		if flag&Lshortfile != 0 {
			short := file
			for i := len(file) - 1; i > 0; i-- {
				if file[i] == '/' {
					short = file[i+1:]
					break
				}
			}
			file = short
		}
		*buf = append(*buf, file...)
		*buf = append(*buf, ':')
		itoa(buf, line, -1)
		*buf = append(*buf, ": "...)
	}
	if flag&Lmsgprefix != 0 {
		*buf = append(*buf, prefix...)
	}
}

var bufferPool = sync.Pool{New: func() any { return new([]byte) }}

func getBuffer() *[]byte {
	p := bufferPool.Get().(*[]byte)
	*p = (*p)[:0]
	return p
}

func putBuffer(p *[]byte) {
	if cap(*p) > 64<<10 {
		*p = nil
	}
	bufferPool.Put(p)
}

// output can take either a calldepth or a pc to get source line information.
// It uses the pc if it is non-zero.
func (l *Logger) output(pc uintptr, calldepth int, appendOutput func([]byte) []byte) error {
	if l.isDiscard.Load() {
		return nil
	}

	now := time.Now() // get this early.

	// Load prefix and flag once so that their value is consistent within
	// this call regardless of any concurrent changes to their value.
	prefix := l.Prefix()
	flag := l.Flags()

	var file string
	var line int
	if flag&(Lshortfile|Llongfile) != 0 {
		if pc == 0 {
			var ok bool
			_, file, line, ok = runtime.Caller(calldepth)
			if !ok {
				file = "???"
				line = 0
			}
		} else {
			fs := runtime.CallersFrames([]uintptr{pc})
			f, _ := fs.Next()
			file = f.File
			if file == "" {
				file = "???"
			}
			line = f.Line
		}
	}

	buf := getBuffer()
	defer putBuffer(buf)
	formatHeader(buf, now, prefix, flag, file, line)
	*buf = appendOutput(*buf)
	if len(*buf) == 0 || (*buf)[len(*buf)-1] != '\n' {
		*buf = append(*buf, '\n')
	}

	l.outMu.Lock()
	defer l.outMu.Unlock()
	_, err := l.out.Write(*buf)
	return err
}

// Printf calls l.Output to print to the logger.
// Arguments are handled in the manner of [fmt.Printf].
func (l *Logger) Printf(format string, v ...any) {
	l.output(0, 2, func(b []byte) []byte {
		return fmt.Appendf(b, format, v...)
	})
}

知识共享许可协议

本作品采用知识共享署名-非商业性使用-相同方式共享 4.0 国际许可协议进行许可。