golang内置的log

今天学习了一下golang内置的log实现，有点小收获。

先来看看它是怎么用的。

import "log"

func main() {
	log.SetPrefix("[logusage]")
	log.SetFlags(log.Ldate|log.Llongfile)

	log.Println("i am log")
	log.Fatalln("i am fatal")
	log.Panicln("i am panic")

}

 log提供的接口也不多，最基础的用法就那几个函数。

log.SetPrefix用来给log内容添加前缀。

log.SetFlags用来设置日志的一系列标志。如log.Ldate表示打印日志的时候的日期，log.Llongfile表示打印日志的语句所在的源码文件完整路径。

运行结果如下所示：

[logusage]2020/07/02 F:/go/src/algorithm/logusage/main.go:9: i am log
[logusage]2020/07/02 F:/go/src/algorithm/logusage/main.go:10: i am fatal

可见log.Panicln语句并没有打印出来，这是为什么呢？

因为log.Fatalln这条语句执行的时候就已经退出程序了，可以看它的实现：
 

func Fatalln(v ...interface{}) {
	std.Output(2, fmt.Sprintln(v...))
	os.Exit(1)
}

我原本以为Fatalln这种只是类似于log.Info(),log.Debug(),log.Error()这种日志等级。

但实际上我想错了，它内部真实的行为其实是这样子的。

查了一下，系统自带的log功能十分简单，就只是单纯的打印日志内容。连很多日志库基本的功能都没有，比如

日志级别：Info，Debug，Error。

日志文件自动切割。

想要更多更丰富的功能只能使用第三方的log库。

但我关心的不是这种简单的用法。因为它用法简单，所以更想看看它是如何实现的。

type Logger struct {
	mu     sync.Mutex // ensures atomic writes; protects the following fields
	prefix string     // prefix to write at beginning of each line
	flag   int        // properties
	out    io.Writer  // destination for output
	buf    []byte     // for accumulating text to write
}

func New(out io.Writer, prefix string, flag int) *Logger {
	return &Logger{out: out, prefix: prefix, flag: flag}
}

var std = New(os.Stderr, "", LstdFlags)

这是它的结构体和创建函数。可以看到这里有个互斥量mu来保证并发环境下的原子写操作。下面看看内部是如何实现写日志的功能的。

func Println(v ...interface{}) {
	std.Output(2, fmt.Sprintln(v...))
}

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
}

为什么加锁操作要放在后面，为什么一进函数内部不马上加锁？

其实这里的now是不用加锁保护的，因为它存储在栈上，每个调用Output函数的上层函数都有一份各自的now，它不会有数据竞争的问题，有数据竞争问题的都是共享的数据，分配在堆上的，所以这里不用加锁保护。

加锁之后就是if语句，但是进入if语句后立马又释放了互斥锁，一直等到if语句最后才又加上互斥锁。

所以我觉得这里加锁的时机很重要。

在if前加锁是为了防止在做if判断语句的时候，防止l.flag被其他goroutine修改。而后面进入if语句后马上有释放了互斥锁，看源码注释生活是因为runtime.Caller()这个函数很expensive。这里是什么意思？什么叫这个函数很expensive？

按照我的理解，估计是这个函数调用要花费的时间稍微长一点，它的功能是获取调用栈信息。因为它要花费更长的时间所以就解锁？这又是什么道理？

假设一个极端情况，如果这个函数执行一次要花费5秒钟，如果这里不解锁，那么并发的所有goroutine调用这个函数的时候都要在这段临界区代码前面排队等待解锁，这样整个软件写日志的功能就容易在这点形成性能瓶颈。那如果在这里解锁有什么好处，又有什么坏处？

如果在这里解锁，那么所有并发goroutine就不用排队等待执行这个费时的函数，而是大家都可以马上执行它，并且把执行结果存储在自己的栈上，注意看这里的file和line是函数内部的变量，是存储在栈上的，所以这段代码是安全的，不会造成数据竞争。这样解决了性能问题，安全性也有保障。

后面再加锁那就是常规操作，为了保证l.buf等等数据不会造成数据竞争。

总结：

如果并发场景下，临界区代码有非常耗时的操作，不防先把临界区解锁，等操作结束后再加锁，耗时操作的结果要放到非竞态数据里去。