golang日志篇-log与fmt区别

最近在排查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()
}

输出结果:

golang线程安全控制台输出.png

从中我们可以看到程序中由于使用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-safe.png

从演示样例中我们可以看到,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的时候是怎么执行的呢？我们看其代码：

golang-os-stderr-information.png

这里实际就是调用了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
)

输出格式样例:

golang-log-flags-format.png

3:将日志信息进行转存,形成日志文件

具体我们可以查看log的new方法

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

log-writer-file-show-code.png

然后直接调用log中的Println的方法输出日志即可,就会将日志内容追加到日志文件中。

最后,打印信息的话一般也不用fmt,fmt一般用来格式化. 所以特殊需求也就不要用fmt了.希望大家有其它方面的个人见解随时私聊我,我们公共成长,一起进步。

1:线程安全层面

1、1 Logger的定义结构

1.2 std及整体结构

1.3 核心函数的实现

1.4 对外接口的实现

2:制定指定的日志内容输出格式

3:将日志信息进行转存,形成日志文件

Recommend

golang fmt占位符

golang---fmt格式“占位符”

Golang标准库——fmt

golang fmt格式“占位符”

[Golang] Create Template Using fmt.Sprintf

[Golang] Caveat of fmt.Fprintf Use

[Golang] Create Error Using fmt.Errorf or errors.New

[Golang] Convert Integer to String via fmt.Sprintf

Go 日志打印 fmt

Golang 记一次log日志不能输出的问题

About Joyk