Skip to content

Commit

Permalink
optimize speed of no-formatter setup
Browse files Browse the repository at this point in the history
  • Loading branch information
@umputun
umputun committed Apr 2, 2019
1 parent a064eac commit e5917fc
Show file tree
Hide file tree
Showing 2 changed files with 87 additions and 54 deletions.
88 changes: 45 additions & 43 deletions logger.go
View file
Expand Up @@ -15,6 +15,7 @@ import (
"os"
"path"
"runtime"
"strconv"
"strings"
"sync"
"text/template"
Expand Down Expand Up @@ -85,27 +86,25 @@ func New(options ...Option) *Logger {
opt(&res)
}

var err error
if res.format == "" {
res.format = res.templateFromOptions()
}

res.templ, err = template.New("lgr").Parse(res.format)
if err != nil {
fmt.Printf("invalid template %s, error %v. switched to %s\n", res.format, err, Short)
res.format = Short
res.templ = template.Must(template.New("lgrDefault").Parse(Short))
}
if res.format != "" {
var err error
res.templ, err = template.New("lgr").Parse(res.format)
if err != nil {
fmt.Printf("invalid template %s, error %v. switched to %s\n", res.format, err, Short)
res.format = Short
res.templ = template.Must(template.New("lgrDefault").Parse(Short))
}

buf := bytes.Buffer{}
if err = res.templ.Execute(&buf, layout{}); err != nil {
fmt.Printf("failed to execute template %s, error %v. switched to %s\n", res.format, err, Short)
res.format = Short
res.templ = template.Must(template.New("lgrDefault").Parse(Short))
buf := bytes.Buffer{}
if err = res.templ.Execute(&buf, layout{}); err != nil {
fmt.Printf("failed to execute template %s, error %v. switched to %s\n", res.format, err, Short)
res.format = Short
res.templ = template.Must(template.New("lgrDefault").Parse(Short))
}
}

res.callerOn = strings.Contains(res.format, "{{.Caller")
res.levelBracesOn = strings.Contains(res.format, "[{{.Level}}]")
res.callerOn = strings.Contains(res.format, "{{.Caller") || res.callerFile || res.callerFunc || res.callerPkg
res.levelBracesOn = strings.Contains(res.format, "[{{.Level}}]") || res.levelBraces
return &res
}

Expand All @@ -128,7 +127,7 @@ func (l *Logger) logf(format string, args ...interface{}) {
return
}

ci := callerInfo{}
var ci callerInfo
if l.callerOn { // optimization to avoid expensive caller evaluation if caller info not in the template
ci = l.reportCaller(l.callerDepth)
}
Expand All @@ -143,14 +142,20 @@ func (l *Logger) logf(format string, args ...interface{}) {
CallerLine: ci.Line,
}

buf := bytes.Buffer{}
err := l.templ.Execute(&buf, elems) // once constructed, a template may be executed safely in parallel.
if err != nil {
fmt.Printf("failed to execute template, %v\n", err) // should never happen
var data []byte
if l.format != "" {
buf := bytes.Buffer{}
err := l.templ.Execute(&buf, elems) // once constructed, a template may be executed safely in parallel.
if err != nil {
fmt.Printf("failed to execute template, %v\n", err) // should never happen
}
data = buf.Bytes()
} else {
// optimized formatter, avoids templates
data = []byte(l.formatWithOptions(elems))
}
buf.WriteString("\n")
data = append(data, '\n')

data := buf.Bytes()
if l.levelBracesOn { // rearrange space in short levels
data = bytes.Replace(data, []byte("[WARN ]"), []byte("[WARN] "), 1)
data = bytes.Replace(data, []byte("[INFO ]"), []byte("[INFO] "), 1)
Expand Down Expand Up @@ -230,41 +235,38 @@ func (l *Logger) reportCaller(calldepth int) (res callerInfo) {
return res
}

// make template from option flags
func (l *Logger) templateFromOptions() (res string) {

const (
// escape { and } from templates to allow "{some/blah}" output for caller
openCallerBrace = `{{"{"}}`
closeCallerBrace = `{{"}"}}`
)
// speed-optimized version of formatter, used with individual options only, i.e. without Format call
func (l *Logger) formatWithOptions(elems layout) (res string) {

orElse := func(flag bool, value string, elseValue string) string {
orElse := func(flag bool, fnTrue func() string, fnFalse func() string) string {
if flag {
return value
return fnTrue()
}
return elseValue
return fnFalse()
}

var parts []string

parts = append(parts, orElse(l.msec, `{{.DT.Format "2006/01/02 15:04:05.000"}}`, `{{.DT.Format "2006/01/02 15:04:05"}}`))
parts = append(parts, orElse(l.levelBraces, `[{{.Level}}]`, `{{.Level}}`))
parts = append(parts, orElse(l.msec,
func() string { return elems.DT.Format("2006/01/02 15:04:05.000") }, func() string { return elems.DT.Format("2006/01/02 15:04:05") }))

parts = append(parts, orElse(l.levelBraces, func() string { return `[` + elems.Level + `]` }, func() string { return elems.Level }))

if l.callerFile || l.callerFunc || l.callerPkg {
var callerParts []string
if v := orElse(l.callerFile, `{{.CallerFile}}:{{.CallerLine}}`, ""); v != "" {
if v := orElse(l.callerFile, func() string { return elems.CallerFile + ":" + strconv.Itoa(elems.CallerLine) }, func() string { return "" }); v != "" {
callerParts = append(callerParts, v)
}
if v := orElse(l.callerFunc, `{{.CallerFunc}}`, ""); v != "" {
if v := orElse(l.callerFunc, func() string { return elems.CallerFunc }, func() string { return "" }); v != "" {
callerParts = append(callerParts, v)
}
if v := orElse(l.callerPkg, `{{.CallerPkg}}`, ""); v != "" {
if v := orElse(l.callerPkg, func() string { return elems.CallerPkg }, func() string { return "" }); v != "" {
callerParts = append(callerParts, v)
}
parts = append(parts, openCallerBrace+strings.Join(callerParts, " ")+closeCallerBrace)
parts = append(parts, "{"+strings.Join(callerParts, " ")+"}")
}
parts = append(parts, "{{.Message}}")

parts = append(parts, elems.Message)
return strings.Join(parts, " ")
}

Expand Down
53 changes: 42 additions & 11 deletions logger_test.go
View file
Expand Up @@ -136,23 +136,43 @@ func TestLoggerWithCallerDepth(t *testing.T) {
"func2) something 123 err\n", rout.String())
}

func TestLogger_templateFromOptions(t *testing.T) {
func TestLogger_formatWithOptions(t *testing.T) {
tbl := []struct {
opts []Option
res string
opts []Option
elems layout
res string
}{
{[]Option{}, `{{.DT.Format "2006/01/02 15:04:05"}} {{.Level}} {{.Message}}`},
{[]Option{Msec}, `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} {{.Message}}`},
{[]Option{Msec, LevelBraces}, `{{.DT.Format "2006/01/02 15:04:05.000"}} [{{.Level}}] {{.Message}}`},
{[]Option{CallerFile}, `{{.DT.Format "2006/01/02 15:04:05"}} {{.Level}} {{"{"}}{{.CallerFile}}:{{.CallerLine}}{{"}"}} {{.Message}}`},
{[]Option{CallerFile, CallerFunc, Msec}, `{{.DT.Format "2006/01/02 15:04:05.000"}} {{.Level}} {{"{"}}{{.CallerFile}}:{{.CallerLine}} {{.CallerFunc}}{{"}"}} {{.Message}}`},
{[]Option{CallerFunc, CallerPkg, Msec, LevelBraces}, `{{.DT.Format "2006/01/02 15:04:05.000"}} [{{.Level}}] {{"{"}}{{.CallerFunc}} {{.CallerPkg}}{{"}"}} {{.Message}}`},
{
[]Option{},
layout{DT: time.Date(2018, 1, 7, 13, 2, 34, 0, time.Local), Message: "blah blah", Level: "INFO "},
"2018/01/07 13:02:34 INFO blah blah",
},
{
[]Option{Msec},
layout{DT: time.Date(2018, 1, 7, 13, 2, 34, 0, time.Local), Message: "blah blah", Level: "DEBUG"},
"2018/01/07 13:02:34.000 DEBUG blah blah",
},
{
[]Option{Msec, LevelBraces},
layout{DT: time.Date(2018, 1, 7, 13, 2, 34, 0, time.Local), Message: "blah blah", Level: "DEBUG"},
"2018/01/07 13:02:34.000 [DEBUG] blah blah",
},
{
[]Option{CallerFile, Msec},
layout{DT: time.Date(2018, 1, 7, 13, 2, 34, 0, time.Local), Message: "blah blah", Level: "DEBUG", CallerFile: "file1.go", CallerLine: 12},
"2018/01/07 13:02:34.000 DEBUG {file1.go:12} blah blah",
},
{
[]Option{CallerFunc, CallerPkg},
layout{DT: time.Date(2018, 1, 7, 13, 2, 34, 0, time.Local), Message: "blah blah", Level: "DEBUG", CallerFunc: "func1", CallerPkg: "pkg"},
"2018/01/07 13:02:34 DEBUG {func1 pkg} blah blah",
},
}

for n, tt := range tbl {
l := New(tt.opts...)
t.Run(strconv.Itoa(n), func(t *testing.T) {
assert.Equal(t, tt.res, l.templateFromOptions())
assert.Equal(t, tt.res, l.formatWithOptions(tt.elems))
})
}
}
Expand Down Expand Up @@ -292,7 +312,7 @@ func TestLoggerOverwriteFormat(t *testing.T) {
assert.Equal(t, "2018/01/07 13:02:34 INFO something 123 err\n", rout.String(), "short format enforced")
}

func BenchmarkNoDbg(b *testing.B) {
func BenchmarkNoDbgNoFormat(b *testing.B) {
rout, rerr := bytes.NewBuffer([]byte{}), bytes.NewBuffer([]byte{})
l := New(Out(rout), Err(rerr))
l.now = func() time.Time { return time.Date(2018, 1, 7, 13, 2, 34, 0, time.Local) }
Expand All @@ -303,6 +323,17 @@ func BenchmarkNoDbg(b *testing.B) {
}
}

func BenchmarkNoDbgFormat(b *testing.B) {
rout, rerr := bytes.NewBuffer([]byte{}), bytes.NewBuffer([]byte{})
l := New(Out(rout), Err(rerr), Format(Short))
l.now = func() time.Time { return time.Date(2018, 1, 7, 13, 2, 34, 0, time.Local) }

e := errors.New("some error")
for n := 0; n < b.N; n++ {
l.Logf("[INFO] test test 123 debug message #%d, %v", n, e)
}
}

func BenchmarkWithDbg(b *testing.B) {
rout, rerr := bytes.NewBuffer([]byte{}), bytes.NewBuffer([]byte{})
l := New(Debug, Format(FullDebug), Out(rout), Err(rerr))
Expand Down

0 comments on commit e5917fc

Please sign in to comment.