From 84eec4236bd05372ca634b79091a44cfcfca54d1 Mon Sep 17 00:00:00 2001 From: Evan Chen Date: Fri, 5 Nov 2021 15:41:54 +0800 Subject: [PATCH] refat: use Fprintf over text/template --- README.md | 18 ++- color.go | 26 ----- log.go | 308 ++++++++++++++++++++-------------------------------- log_test.go | 83 ++++++++------ std.go | 63 +++-------- util.go | 9 -- 6 files changed, 205 insertions(+), 302 deletions(-) diff --git a/README.md b/README.md index a3f1712..575b662 100644 --- a/README.md +++ b/README.md @@ -3,4 +3,20 @@ ## Test Mem: `go test -o tests/test.exe -memprofile tests/mem && go tool pprof -http : tests/mem` -Cpu: `go test -o tests/test.exe -cpuprofile tests/cpu && go tool pprof -http : tests/cpu` \ No newline at end of file +Cpu: `go test -o tests/test.exe -cpuprofile tests/cpu && go tool pprof -http : tests/cpu` + +## Bench + +``` +v0.0.1 +BenchmarkDefault-8 8512 158272 ns/op +BenchmarkSub1-8 6140 166344 ns/op +BenchmarkDefault-8 6190 189078 ns/op 19522 B/op 387 allocs/op +BenchmarkSub1-8 6222 200761 ns/op 20511 B/op 435 allocs/op + +test(v0.0.2) +BenchmarkDefault-8 12410 109143 ns/op +BenchmarkSub1-8 10000 113340 ns/op +BenchmarkDefault-8 12186 112974 ns/op 21944 B/op 303 allocs/op +BenchmarkSub1-8 10000 114026 ns/op 22702 B/op 363 allocs/op +``` \ No newline at end of file diff --git a/color.go b/color.go index d6dba13..6fe6049 100644 --- a/color.go +++ b/color.go @@ -3,7 +3,6 @@ package klog import ( "fmt" "strconv" - "text/template" "kumoly.io/lib/klog/color" ) @@ -24,28 +23,3 @@ func (l *Logger) M(s interface{}, attrs ...color.Attribute) string { } return fmt.Sprintf("\033[%sm%s\033[0m", styles, s) } - -func (l *Logger) setColorMap(funcMap template.FuncMap) { - funcMap["M"] = l.M - if l.color { - funcMap["red"] = func(s interface{}) string { return fmt.Sprintf("\033[91m%s\033[0m", s) } - funcMap["redl"] = func(s interface{}) string { return fmt.Sprintf("\033[31m%s\033[0m", s) } - funcMap["green"] = func(s interface{}) string { return fmt.Sprintf("\033[92m%s\033[0m", s) } - funcMap["yellow"] = func(s interface{}) string { return fmt.Sprintf("\033[93m%s\033[0m", s) } - funcMap["blue"] = func(s interface{}) string { return fmt.Sprintf("\033[94m%s\033[0m", s) } - funcMap["magenta"] = func(s interface{}) string { return fmt.Sprintf("\033[95m%s\033[0m", s) } - funcMap["cyan"] = func(s interface{}) string { return fmt.Sprintf("\033[96m%s\033[0m", s) } - funcMap["white"] = func(s interface{}) string { return fmt.Sprintf("\033[97m%s\033[0m", s) } - return - } - funcMap["red"] = func(s string) string { return s } - funcMap["redl"] = func(s string) string { return s } - funcMap["green"] = func(s string) string { return s } - funcMap["yellow"] = func(s string) string { return s } - funcMap["blue"] = func(s string) string { return s } - funcMap["magenta"] = func(s string) string { return s } - funcMap["cyan"] = func(s string) string { return s } - funcMap["white"] = func(s string) string { return s } -} - -// func diff --git a/log.go b/log.go index ef24528..e936451 100644 --- a/log.go +++ b/log.go @@ -6,79 +6,45 @@ import ( "io" "os" "sync" - "text/template" "time" "github.com/mattn/go-isatty" + "kumoly.io/lib/klog/color" ) +type Llevel int + const ( - Lerror = 1 << iota + Lerror Llevel = 1 << iota Ldebug Lwarn Linfo ) -type tout int - -const ( - terror tout = iota - tdebug - tinfo - twarn -) - var lock sync.Mutex var PROD = true var LEVEL = Lerror | Linfo -const ( - DEFAULT_ERR = `{{Time}} [{{"ERROR"|red}}]` + - `{{if .System}}({{.System|cyan}}){{end}} ` + - `{{.Caller}} {{.Message}}` + - `{{if .Fields}} {{.Fields|json|green}}{{end}}{{"\n"}}` + - `{{if .Stack}}{{.Stack|redl}}{{end}}` - DEFAULT_DEBUG = `{{Time}} [{{"DEBUG"|magenta}}]` + - `{{if .System}}({{.System|cyan}}){{end}} ` + - `{{.Caller}} {{.Message}}` + - `{{if .Fields}} {{.Fields|json|green}}{{end}}{{"\n"}}` + - `{{if .Stack}}{{.Stack|redl}}{{end}}` - DEFAULT_WARN = `{{Time}} [{{"WARN"|yellow}} ]` + - `{{if .System}}({{.System|cyan}}){{end}} ` + - `{{.Message}}` + - `{{if .Fields}} {{.Fields|json|green}}{{end}}{{"\n"}}` - DEFAULT_INFO = `{{Time}} [{{"INFO"|blue}} ]` + - `{{if .System}}({{.System|cyan}}){{end}} ` + - `{{.Message}}` + - `{{if .Fields}} {{.Fields|json|green}}{{end}}{{"\n"}}` -) - -type LogFormater struct { - ErrTmplStr string - WarnTmplStr string - InfoTmplStr string - DebugTmplStr string -} - type H map[string]interface{} type Ldata struct { Message string - System string + Time time.Time + Level Llevel // Caller only evaluates in DEBUG, and ERROR calls Caller string // Stack only eval when !PROD and {DEBUG, ERROR} Stack string - Fields H + Fields *H Color bool } type Logger struct { - system string + System string color bool explicit bool @@ -86,38 +52,103 @@ type Logger struct { err io.Writer out io.Writer - formatter *LogFormater - funcMap template.FuncMap + printer Printer - tmpl *template.Template - err_tmpl *template.Template - debug_tmpl *template.Template - warn_tmpl *template.Template - info_tmpl *template.Template - subs []*Logger + subs []*Logger +} + +type Printer func(io.Writer, *Ldata, *Logger) + +func DefaultPrinter() Printer { + return func(w io.Writer, d *Ldata, l *Logger) { + var level string + caller := "" + sys := "" + if l.System != "" { + sys = fmt.Sprintf("(%s)", l.System) + } + fields := []byte{} + if d.Fields != nil { + b, err := json.Marshal(d.Fields) + if err != nil { + fields = b + } + } + switch d.Level { + case Lerror: + level = l.M("ERROR", color.FgHiRed) + caller = d.Caller + case Ldebug: + level = l.M("DEBUG", color.FgHiMagenta) + caller = d.Caller + case Lwarn: + level = l.M("WARN ", color.FgHiYellow) + case Linfo: + level = l.M("INFO ", color.FgHiBlue) + } + _, err := fmt.Fprintf(w, "%s [%s]%s%s %s%s\n%s", + d.Time.Format("2006/01/02 15:04:05"), + level, l.M(sys, color.FgHiCyan), + caller, l.M(d.Message, color.FgHiGreen), fields, + l.M(d.Stack, color.FgRed), + ) + if err != nil { + fmt.Println(err) + } + } +} + +func (l *Logger) output(lev Llevel, depth int, fields H, v ...interface{}) { + if LEVEL&lev == 0 { + return + } + msg := fmt.Sprint(v...) + data := &Ldata{ + Fields: &fields, + Message: msg, + Level: lev, + Time: time.Now(), + Caller: caller(depth), + Color: l.color, + } + switch lev { + case Lerror: + if !PROD { + data.Stack = stack() + } + case Ldebug: + if !PROD { + data.Stack = stack() + } + } + lock.Lock() + defer lock.Unlock() + if lev == Lerror || lev == Ldebug { + l.printer(l.err, data, l) + } else { + l.printer(l.out, data, l) + } } func New(name string) *Logger { l := &Logger{ - system: name, - err: os.Stderr, - out: os.Stdout, - color: true, - formatter: NewLogFormater(), + System: name, + err: os.Stderr, + out: os.Stdout, + color: true, + printer: DefaultPrinter(), } - l.Reload() + l.guessColor() return l } func (l *Logger) Sub(sys string) *Logger { ret := &Logger{ - system: sys, - err: l.err, - out: l.out, - color: l.color, - formatter: l.formatter, - - tmpl: l.tmpl, + System: sys, + err: l.err, + out: l.out, + color: l.color, + printer: l.printer, } if l.subs == nil { l.subs = make([]*Logger, 0) @@ -150,176 +181,73 @@ func (l *Logger) SetColorAll(c bool) { func (l *Logger) SetErrOutput(err io.Writer) { l.err = err + l.guessColor() } func (l *Logger) SetErrOutputAll(err io.Writer) { for _, v := range getAllOffsprings(l) { - v.err = err + v.SetErrOutput(err) } } func (l *Logger) SetOutput(out io.Writer) { l.out = out + l.guessColor() } func (l *Logger) SetOutputAll(out io.Writer) { for _, v := range getAllOffsprings(l) { - v.out = out + v.SetOutput(out) } } -func (l *Logger) Reload() error { - if !l.explicit { - l.guessColor() - } - return l.ParseTmpl() +func (l *Logger) SetPrinter(p Printer) { + l.printer = p } -func (l *Logger) ReloadAll() error { +func (l *Logger) SetPrinterAll(p Printer) { for _, v := range getAllOffsprings(l) { - if err := v.Reload(); err != nil { - return err - } - } - return nil -} - -func NewLogFormater() *LogFormater { - return &LogFormater{ - ErrTmplStr: DEFAULT_ERR, - WarnTmplStr: DEFAULT_WARN, - InfoTmplStr: DEFAULT_INFO, - DebugTmplStr: DEFAULT_DEBUG, + v.SetPrinter(p) } } -func (l *Logger) DefaultFuncMap() template.FuncMap { - funcMap := template.FuncMap{ - "Time": func() string { return time.Now().Format("2006/01/02 15:04:05") }, - "json": func(i interface{}) (string, error) { r, err := json.Marshal(i); return string(r), err }, - } - return funcMap -} - -func (l *Logger) ParseTmpl() error { - if l.funcMap == nil { - l.funcMap = l.DefaultFuncMap() - } - funcMap := copyFuncMap(l.funcMap) - l.setColorMap(funcMap) - - tmpl, err := template.New("info_tmpl").Funcs(funcMap).Parse(l.formatter.InfoTmplStr) - if err != nil { - return err - } - tmpl, err = tmpl.New("err_tmpl").Parse(l.formatter.ErrTmplStr) - if err != nil { - return err - } - tmpl, err = tmpl.New("warn_tmpl").Parse(l.formatter.WarnTmplStr) - if err != nil { - return err - } - tmpl, err = tmpl.New("debug_tmpl").Parse(l.formatter.DebugTmplStr) - if err != nil { - return err - } - l.tmpl = tmpl - return nil -} - -func (l *Logger) SetTmpl(formatter *LogFormater, funcMap template.FuncMap) { - l.formatter = formatter - if funcMap != nil { - l.funcMap = funcMap - } -} - -func (l *Logger) output(t tout, depth int, stack string, fields H, v ...interface{}) { - msg := fmt.Sprint(v...) - data := Ldata{ - Fields: fields, - Message: msg, - System: l.system, - Caller: caller(depth), - Color: l.color, - Stack: stack, - } - lock.Lock() - defer lock.Unlock() - var err error - switch t { - case terror: - if LEVEL&Lerror == 0 { - return - } - err = l.tmpl.ExecuteTemplate(l.err, "err_tmpl", data) - case tdebug: - if LEVEL&Ldebug == 0 { - return - } - err = l.tmpl.ExecuteTemplate(l.err, "debug_tmpl", data) - case twarn: - if LEVEL&Lwarn == 0 { - return - } - err = l.tmpl.ExecuteTemplate(l.out, "warn_tmpl", data) - case tinfo: - if LEVEL&Linfo == 0 { - return - } - err = l.tmpl.ExecuteTemplate(l.out, "info_tmpl", data) - } - if err != nil { - fmt.Fprintln(l.err, "[FATAL] Logger error:", err) - panic(err) - } -} +// func (l *Logger) DefaultFuncMap() template.FuncMap { +// funcMap := template.FuncMap{ +// "Time": func() string { return time.Now().Format("2006/01/02 15:04:05") }, +// "json": func(i interface{}) (string, error) { r, err := json.Marshal(i); return string(r), err }, +// } +// return funcMap +// } func (l *Logger) ErrorF(fields H, v ...interface{}) { - if PROD { - l.output(terror, 3, "", fields, v...) - } else { - l.output(terror, 3, stack(), fields, v...) - } + l.output(Lerror, 3, fields, v...) + } func (l *Logger) Error(v ...interface{}) { - if PROD { - l.output(terror, 3, "", H{}, v...) - } else { - l.output(terror, 3, stack(), H{}, v...) - } + l.output(Lerror, 3, H{}, v...) } func (l *Logger) DebugF(fields H, v ...interface{}) { - if PROD { - l.output(tdebug, 3, "", fields, v...) - } else { - l.output(tdebug, 3, stack(), fields, v...) - } + l.output(Ldebug, 3, fields, v...) } func (l *Logger) Debug(v ...interface{}) { - if PROD { - l.output(tdebug, 3, "", H{}, v...) - } else { - l.output(tdebug, 3, stack(), H{}, v...) - } + l.output(Ldebug, 3, H{}, v...) } func (l *Logger) WarnF(fields H, v ...interface{}) { - l.output(twarn, 3, "", fields, v...) + l.output(Lwarn, 3, fields, v...) } func (l *Logger) Warn(v ...interface{}) { - l.output(twarn, 3, "", H{}, v...) + l.output(Lwarn, 3, H{}, v...) } func (l *Logger) InfoF(fields H, v ...interface{}) { - l.output(tinfo, 3, "", fields, v...) + l.output(Linfo, 3, fields, v...) } func (l *Logger) Info(v ...interface{}) { - l.output(tinfo, 3, "", H{}, v...) + l.output(Linfo, 3, H{}, v...) } diff --git a/log_test.go b/log_test.go index ba177ec..51355a9 100644 --- a/log_test.go +++ b/log_test.go @@ -61,32 +61,6 @@ func TestSubProd(t *testing.T) { l.InfoF(H{"Test": "set"}, "TestSubProd") } -func TestCustTmpl(t *testing.T) { - PROD = true - l := Sub("TestCustTmpl") - CustFormater := NewLogFormater() - CustFormater.InfoTmplStr = `{{Time}} [{{ M "INFO" 104 93 9}} ]` + - `{{if .System}}({{M .System 96}}){{end}} ` + - `Hello, {{.Fields.Name}}. {{.Message}}{{"\n"}}` - CustFormater.ErrTmplStr = `{{Time}} [{{ M "ERROR" 91 43 1}}]` + - `{{if .System}}({{M .System 96}}){{end}} ` + - `NO! {{.Fields.Name}} {{M .Message 31 3}} {{"\n"}}` - l.SetTmpl(CustFormater, nil) - l.Reload() - l.ErrorF(H{"Name": "Brandon"}, "TestCustTmpl") - l.InfoF(H{"Name": "Brandon"}, "TestCustTmpl") - - SetTmpl(CustFormater, nil) - Reload() - - ErrorF(H{"Name": "Brandon"}, "TestCustTmpl std") - InfoF(H{"Name": "Brandon"}, "TestCustTmpl std") - - //reset - SetTmpl(NewLogFormater(), nil) - Reload() -} - func TestColoring(t *testing.T) { l := Sub("color") l.Error(l.M("Hello", c.BgHiGreen, c.Italic, c.FgWhite), ", ", l.M("world", c.FgBlue, c.BgHiYellow)) @@ -104,7 +78,6 @@ func TestToFile(t *testing.T) { } l.SetOutput(f) l.SetErrOutput(f) - l.Reload() l.Error("TestToFile") l.Debug("TestToFile") @@ -112,7 +85,6 @@ func TestToFile(t *testing.T) { l.Info("TestToFile") l.SetColor(true) - l.Reload() l.Error("TestToFile colored") l.Debug("TestToFile colored") l.Warn("TestToFile colored") @@ -129,17 +101,17 @@ func TestApplyChild(t *testing.T) { l2.Info("child2") l3.Info("child3") l.SetOutputAll(io.Discard) - l.ReloadAll() + l1.Info("child1-discard") l2.Info("child2-discard") l3.Info("child3-discard") SetOutputAll(os.Stdout) - ReloadAll() + l1.Info("child1-stdout") l2.Info("child2-stdout") l3.Info("child3-stdout") SetColorAll(false) - ReloadAll() + l1.Info("child1-nocolor") l2.Info("child2-nocolor") l3.Info("child3-nocolor") @@ -152,3 +124,52 @@ func TestDefaultLogger(t *testing.T) { l.Warn("TestDefaultLogger") l.Info("TestDefaultLogger") } + +func BenchmarkDefault(b *testing.B) { + SetErrOutput(io.Discard) + SetOutput(io.Discard) + LEVEL = 15 + for i := 0; i < b.N; i++ { + PROD = true + Error("err in", "BenchmarkDefault: ", i) + ErrorF(H{"test": "fields"}, "err in", "BenchmarkDefault: ", i) + Debug("err in", "BenchmarkDefault: ", i) + DebugF(H{"test": "fields"}, "err in", "BenchmarkDefault: ", i) + Warn("err in", "BenchmarkDefault: ", i) + WarnF(H{"test": "fields"}, "err in", "BenchmarkDefault: ", i) + } + for i := 0; i < b.N; i++ { + PROD = false + Error("err in", "BenchmarkDefault: ", i) + ErrorF(H{"test": "fields"}, "err in", "BenchmarkDefault: ", i) + Debug("err in", "BenchmarkDefault: ", i) + DebugF(H{"test": "fields"}, "err in", "BenchmarkDefault: ", i) + Warn("err in", "BenchmarkDefault: ", i) + WarnF(H{"test": "fields"}, "err in", "BenchmarkDefault: ", i) + } +} + +func BenchmarkSub1(b *testing.B) { + LEVEL = 15 + l := Sub("Sub1") + SetErrOutput(io.Discard) + SetOutput(io.Discard) + for i := 0; i < b.N; i++ { + PROD = true + l.Error("err in", "BenchmarkDefault: ", i) + l.ErrorF(H{"test": "fields"}, "err in", "BenchmarkSub1: ", i) + l.Debug("err in", "BenchmarkDefault: ", i) + l.DebugF(H{"test": "fields"}, "err in", "BenchmarkSub1: ", i) + l.Warn("err in", "BenchmarkDefault: ", i) + l.WarnF(H{"test": "fields"}, "err in", "BenchmarkSub1: ", i) + } + for i := 0; i < b.N; i++ { + PROD = false + l.Error("err in", "BenchmarkDefault: ", i) + l.ErrorF(H{"test": "fields"}, "err in", "BenchmarkSub1: ", i) + l.Debug("err in", "BenchmarkDefault: ", i) + l.DebugF(H{"test": "fields"}, "err in", "BenchmarkSub1: ", i) + l.Warn("err in", "BenchmarkDefault: ", i) + l.WarnF(H{"test": "fields"}, "err in", "BenchmarkSub1: ", i) + } +} diff --git a/std.go b/std.go index f601a5b..5070be7 100644 --- a/std.go +++ b/std.go @@ -2,7 +2,6 @@ package klog import ( "io" - "text/template" "kumoly.io/lib/klog/color" ) @@ -13,6 +12,16 @@ func DefaultLogger() *Logger { return std } +func SetPrinter(p Printer) { + std.printer = p +} + +func SetPrinterAll(p Printer) { + for _, v := range getAllOffsprings(std) { + v.SetPrinter(p) + } +} + func M(s interface{}, attrs ...color.Attribute) string { return std.M(s, attrs...) } @@ -45,70 +54,34 @@ func SetOutputAll(out io.Writer) { std.SetOutputAll(out) } -func Reload() error { - return std.Reload() -} - -func ReloadAll() error { - return std.ReloadAll() -} - -func DefaultFuncMap() template.FuncMap { - return std.DefaultFuncMap() -} - -func ParseTmpl() error { - return std.ParseTmpl() -} - -func SetTmpl(formatter *LogFormater, funcMap template.FuncMap) { - std.SetTmpl(formatter, funcMap) -} - func ErrorF(fields H, v ...interface{}) { - if PROD { - std.output(terror, 3, "", fields, v...) - } else { - std.output(terror, 3, stack(), fields, v...) - } + std.output(Lerror, 3, fields, v...) } func Error(v ...interface{}) { - if PROD { - std.output(terror, 3, "", H{}, v...) - } else { - std.output(terror, 3, stack(), H{}, v...) - } + std.output(Lerror, 3, H{}, v...) } func DebugF(fields H, v ...interface{}) { - if PROD { - std.output(tdebug, 3, "", fields, v...) - } else { - std.output(tdebug, 3, stack(), fields, v...) - } + std.output(Ldebug, 3, fields, v...) } func Debug(v ...interface{}) { - if PROD { - std.output(tdebug, 3, "", H{}, v...) - } else { - std.output(tdebug, 3, stack(), H{}, v...) - } + std.output(Ldebug, 3, H{}, v...) } func WarnF(fields H, v ...interface{}) { - std.output(twarn, 3, "", fields, v...) + std.output(Lwarn, 3, fields, v...) } func Warn(v ...interface{}) { - std.output(twarn, 3, "", H{}, v...) + std.output(Lwarn, 3, H{}, v...) } func InfoF(fields H, v ...interface{}) { - std.output(tinfo, 3, "", fields, v...) + std.output(Linfo, 3, fields, v...) } func Info(v ...interface{}) { - std.output(tinfo, 3, "", H{}, v...) + std.output(Linfo, 3, H{}, v...) } diff --git a/util.go b/util.go index 6222f41..ea6ecfa 100644 --- a/util.go +++ b/util.go @@ -3,7 +3,6 @@ package klog import ( "fmt" "runtime" - "text/template" ) func caller(depth int) string { @@ -39,11 +38,3 @@ func getAllOffsprings(l *Logger) []*Logger { } return loggers } - -func copyFuncMap(source template.FuncMap) template.FuncMap { - dest := template.FuncMap{} - for k, v := range source { - dest[k] = v - } - return dest -}