Golang Log 优化

目前日志的调用过程：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
// Debugf ...
func Debugf(ctx context.Context, format string, v ...interface{}) {
	logger.WithDepth(4).Debugf(ctx, format, v...)
}

// WithDepth returns cloned logger with new depth
func (l *Logger) WithDepth(depth int) *Logger {
	r := l.clone()
	r.callDepth = depth

	return r
}

func (l *Logger) clone() *Logger {
	return &Logger{
		out:       l.out,
		fmtter:    l.fmtter,
		lvl:       l.lvl,
		callDepth: l.callDepth,
		skipLine:  l.skipLine,
		fields:    l.fields,
		fieldsStr: l.fieldsStr,
		mu:        l.mu,
	}
}


// Debugf ...
func (l *Logger) Debugf(format string, v ...interface{}) {
	if l.lvl <= DebugLevel {
		record := NewRecord(time.Now(), fmt.Sprintf(format, v...), l.getLine(), DebugLevel)
		l.output(record)
	}
}

func (l *Logger) getLine() string {
	var str string
	if !l.skipLine {
		str = line(l.callDepth)
	}

	str = str + l.fieldsStr

	if str != "" {
		str = str + ":"
	}

	return str
}


func (l *Logger) output(record *Record) (err error) {
	b := l.fmtter.Format(record)

	l.mu.Lock()
	defer l.mu.Unlock()

	_, err = l.out.Write(b)

	return
}


// Format formats the logs as "time [level] line message"
func (t *TextFormatter) Format(r *Record) (b []byte, err error) {
	s := fmt.Sprintf("%s [%s] ", r.Time.Format(t.timeFormat), r.Lvl.string())

	if len(r.Line) != 0 {
		s = s + r.Line + " "
	}

	if len(r.Msg) != 0 {
		s = s + r.Msg
	}

	b = []byte(s)

	if len(b) == 0 || b[len(b)-1] != '\n' {
		b = append(b, '\n')
	}

	return
}

以上将整个log的调用流程的主要函数都列出来，方便后面优化做对照。

优先可以优化的就是Format，可以看到在Format中用到了fmt.Sprintf，fmt.Sprintf底层用到了反射对接受类型interface{}的处理；

其次，字符串拼接的是原生的+号拼接法。

我们先对这两个地方做优化，并做响应的测试，源码如下：

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
var (
	concatSteps = 100
	subStr      = "s"
	l           = "11111111111111"
	expectedStr = strings.Repeat(subStr, concatSteps)
)

// 优化掉+号字符串拼接方式
func (t *TextFormatter) Format(r *Record) []byte {
	var builder bytes.Buffer

	//builder.WriteString(fmt.Sprintf("%s [%s] ", r.Time.Format(t.timeFormat), r.Lvl.string()))
	builder.WriteString(r.Time.Format(t.timeFormat))
	builder.WriteString("[" + r.Lvl.string() + "]")
	if len(r.Line) != 0 {
		builder.WriteString(r.Line)
		builder.WriteString(" ")
	}

	if len(r.Msg) != 0 {
		builder.WriteString(r.Msg)
	}
	builder.WriteByte('\n')

	return builder.Bytes()
}

// 优化掉fmt.Sprintf
func (t *TextFormatter) Format2(r *Record) []byte {
	var builder bytes.Buffer

	builder.WriteString(fmt.Sprintf("%s [%s] ", r.Time.Format(t.timeFormat), r.Lvl.string()))
	if len(r.Line) != 0 {
		builder.WriteString(r.Line)
		builder.WriteString(" ")
	}

	if len(r.Msg) != 0 {
		builder.WriteString(r.Msg)
	}
	builder.WriteByte('\n')

	return builder.Bytes()
}



// 这个是原生的log方式
func (t *TextFormatter) Format3(r *Record) (b []byte, err error) {
	s := fmt.Sprintf("%s [%s] ", r.Time.Format(t.timeFormat), r.Lvl.string())

	if len(r.Line) != 0 {
		s = s + r.Line + " "
	}

	if len(r.Msg) != 0 {
		s = s + r.Msg
	}

	b = []byte(s)

	if len(b) == 0 || b[len(b)-1] != '\n' {
		b = append(b, '\n')
	}

	return
}

func BenchmarkTextFormatter_Format(b *testing.B) {
	f := NewTextFormatter()
	for i := 0; i < b.N; i++ {
		f.Format(&Record{
			Time: time.Now(),
			Msg:  expectedStr,
			Line: l,
			Lvl:  0,
		})
	}
}

func BenchmarkTextFormatter_Format2(b *testing.B) {
	f := NewTextFormatter()
	for i := 0; i < b.N; i++ {
		f.Format2(&Record{
			Time: time.Now(),
			Msg:  expectedStr,
			Line: l,
			Lvl:  0,
		})
	}
}

func BenchmarkTextFormatter_Format3(b *testing.B) {
	f := NewTextFormatter()
	for i := 0; i < b.N; i++ {
		f.Format3(&Record{
			Time: time.Now(),
			Msg:  expectedStr,
			Line: l,
			Lvl:  0,
		})
	}
}

benchmark结果如下：

1
2
3
4
5
6
BenchmarkTextFormatter_Format
BenchmarkTextFormatter_Format-12     	 2823270	       426.3 ns/op
BenchmarkTextFormatter_Format2
BenchmarkTextFormatter_Format2-12    	 2076091	       582.5 ns/op
BenchmarkTextFormatter_Format3
BenchmarkTextFormatter_Format3-12    	 1644376	       661.7 ns/op

最终从 661.7ns优化到426.3ns 优化幅度达到35%之多。

Contents