最近在排查golang服务上报丢失日志的问题。发现服务中记录日志的操作大部分使用都是golang log包下的工具类进行操作的,那么log与fmt二者有什么区别？通过下面的样例来具体了解下二者的区别。
1:线程安全层面
我们可以运行以下示例
func TestFmtlog(t *testing.T) {
group := sync.WaitGroup{}
group.Add(3)
for i := 0; i < 3; i++ {
go func() {
log.Printf(" %s\n", "变量1")
log.Printf(" %s\n", "变量2")
sigTerm := syscall.Signal(15)
log.Println(reflect.TypeOf(sigTerm))
fmt.Println("变量3")
fmt.Println("变量4")
fmt.Printf("\n")
group.Done()
}()
}
group.Wait()
}输出结果:
从中我们可以看到程序中由于使用fmt输出的顺序并不是一致的,也就是fm并不是线程安全的,那么我们试下去掉fmt的输出效果呢?
代码:
func TestFmtlog(t *testing.T) {
group := sync.WaitGroup{}
group.Add(3)
for i := 0; i < 3; i++ {
go func() {
log.Printf(" %s\n", "变量1")
log.Printf(" %s\n", "变量2")
group.Done()
}()
}
group.Wait()
}输出效果:
从演示样例中我们可以看到,log.Println是线程安全的。到底是不是这样呢？我们先看下
1、1 Logger的定义结构
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
}主要有5个成员,分别的含义:
prefix:表示Log前缀的.
flag:表示Log头标签的
out:Log的输出目的地。
buf是一个字节数组，主要用来存放即将刷入out的内容，相当于一个临时缓存，在对输出内容进行序列化时作为存储目的地。
mu是一个mutex主要用来作线程安全的实习，当有多个goroutine同时往一个目的刷内容的时候，通过mutex保证每次写入是一条完整的信息。
1.2 std及整体结构
log模块提供了一套包级别的简单接口,使用该接口可以直接将日志内容打印到标准错误。那么该过程是怎么实现的呢？其实就是通过一个内置的Logger类型的变量”std” 来实现的。该变量使用：
var std = New(os.Stderr, "", LstdFlags)进行初始化，默认输出到系统的标准输出 “os.Stderr” ,前缀为空，使用日期加时间作为Log抬头。
当我们调用 log.Print的时候是怎么执行的呢？我们看其代码：
这里实际就是调用了Logger对象的 Output方法，将日志内容按照fmt包中约定的格式转义后传给Output。Output定义如下 :
func (l *Logger) Output(calldepth int, s string) error 其中s为日志没有加前缀和Log抬头的具体内容，xxxxx 。该函数执行具体的将日志刷入到对应的位置。
1.3 核心函数的实现
Logger.Output是执行具体的将日志刷入到对应位置的方法。
该方法首先根据需要获得当前时间和调用该方法的文件及行号信息。然后调用formatHeader方法将Log的前缀和Log抬头先格式化好 放入Logger.buf中，然后再将Log的内容存入到Logger.buf中，最后调用Logger.out.Write方法将完整的日志写入到输出目的地中。
由于写入文件以及拼接buf的过程是线程非安全的，因此使用mutex保证每次写入的原子性。
l.mu.Lock()
defer l.mu.Unlock()将buf的拼接和文件的写入放入这个后面，使得在多个goroutine使用同一个Logger对象是，不会弄乱buf，也不会杂糅的写入。
该方法的第一个参数最终会传递给runtime.Caller的skip，指的是跳过的栈的深度。这里我记住给2就可以了。这样就会得到我们调用log 是所处的位置。
在golang的注释中说锁住runtime.Caller的过程比较重,这里的Logger里带有一个Mutex锁，方便在高并发或者多协程的时候保护上下文数据一致,只是从代码中看到其在这里把锁打开了。
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()
}在formatHeader里面首先将前缀直接复制到Logger.buf中,然后根据flag选择Log抬头的内容，这里用到了一个log模块实现的itoa的方法，作用类似c的itoa,将一个整数转换成一个字符串。只是其转换后将结果直接追加到了buf的尾部。
纵观整个实现，最值得学习的就是线程安全的部分。在什么位置合适做怎样的同步操作。
1.4 对外接口的实现
在了解了核心格式化和输出结构后，在看其封装就非常简单了，几乎都是首先用Output进行日志的记录，然后在必要的时候 做os.exit或者panic的操作，这里看下Fatal的实现。
func (l *Logger) Fatal(v ...interface{}) {
l.Output(2, fmt.Sprint(v...))
os.Exit(1)
}
// Fatalf is equivalent to l.Printf() followed by a call to os.Exit(1).
func (l *Logger) Fatalf(format string, v ...interface{}) {
l.Output(2, fmt.Sprintf(format, v...))
os.Exit(1)
}
// Fatalln is equivalent to l.Println() followed by a call to os.Exit(1).
func (l *Logger) Fatalln(v ...interface{}) {
l.Output(2, fmt.Sprintln(v...))
os.Exit(1)
}这里也验证了我们之前做的Panic的结果，先做输出日志操作。再进行panic。
2:制定指定的日志内容输出格式
我们可以通过以下代码进行对log输出的日志进行输出详细的日志信息
#指定输出date与time输出以及执行代码日志的行号
log.SetFlags(log.LstdFlags | log.Llongfile)
具体更多选项设置可以参见log中源码
const (
Ldate = 1 << iota // the date in the local time zone: 2009/01/23
Ltime // the time in the local time zone: 01:23:23
Lmicroseconds // microsecond resolution: 01:23:23.123123. assumes Ltime.
Llongfile // full file name and line number: /a/b/c/d.go:23
Lshortfile // final file name element and line number: d.go:23. overrides Llongfile
LUTC // if Ldate or Ltime is set, use UTC rather than the local time zone
LstdFlags = Ldate | Ltime // initial values for the standard logger
)输出格式样例:
3:将日志信息进行转存,形成日志文件
具体我们可以查看log的new方法
func New(out io.Writer, prefix string, flag int) *Logger {
return &Logger{out: out, prefix: prefix, flag: flag}
}
然后直接调用log中的Println的方法输出日志即可,就会将日志内容追加到日志文件中。
4:结论
最后,打印信息的话 一般也不用fmt,fmt一般用来格式化. 所以特殊需求也就不要用fmt了.希望大家有其它方面的个人见解随时私聊我,我们公共成长,一起进步。
