perf: use fprintf

README.md

@@ -4,3 +4,21 @@
 
 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`
+
+## Bench
+
+```
+go test -bench . -run none --benchmem
+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
+
+go test -bench . -run none --benchmem
+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
+```

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

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
+	printer Printer
-	funcMap   template.FuncMap
 
-	tmpl       *template.Template
-	err_tmpl   *template.Template
-	debug_tmpl *template.Template
-	warn_tmpl  *template.Template
-	info_tmpl  *template.Template
 	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,
+		System:  name,
 		err:     os.Stderr,
 		out:     os.Stdout,
 		color:   true,
-		formatter: NewLogFormater(),
+		printer: DefaultPrinter(),
 	}
-	l.Reload()
+	l.guessColor()
 	return l
 }
 
 func (l *Logger) Sub(sys string) *Logger {
 	ret := &Logger{
-		system:    sys,
+		System:  sys,
 		err:     l.err,
 		out:     l.out,
 		color:   l.color,
-		formatter: l.formatter,
+		printer: l.printer,
-
-		tmpl: l.tmpl,
 	}
 	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 {
+func (l *Logger) SetPrinter(p Printer) {
-	if !l.explicit {
+	l.printer = p
-		l.guessColor()
-	}
-	return l.ParseTmpl()
 }
 
-func (l *Logger) ReloadAll() error {
+func (l *Logger) SetPrinterAll(p Printer) {
 	for _, v := range getAllOffsprings(l) {
-		if err := v.Reload(); err != nil {
+		v.SetPrinter(p)
-			return err
-		}
-	}
-	return nil
-}
-
-func NewLogFormater() *LogFormater {
-	return &LogFormater{
-		ErrTmplStr:   DEFAULT_ERR,
-		WarnTmplStr:  DEFAULT_WARN,
-		InfoTmplStr:  DEFAULT_INFO,
-		DebugTmplStr: DEFAULT_DEBUG,
 	}
 }
 
-func (l *Logger) DefaultFuncMap() template.FuncMap {
+// func (l *Logger) DefaultFuncMap() template.FuncMap {
-	funcMap := template.FuncMap{
+// 	funcMap := template.FuncMap{
-		"Time": func() string { return time.Now().Format("2006/01/02 15:04:05") },
+// 		"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 },
+// 		"json": func(i interface{}) (string, error) { r, err := json.Marshal(i); return string(r), err },
-	}
+// 	}
-	return funcMap
+// 	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) ErrorF(fields H, v ...interface{}) {
-	if PROD {
+	l.output(Lerror, 3, fields, v...)
-		l.output(terror, 3, "", fields, v...)
+
-	} else {
-		l.output(terror, 3, stack(), fields, v...)
-	}
 }
 
 func (l *Logger) Error(v ...interface{}) {
-	if PROD {
+	l.output(Lerror, 3, H{}, v...)
-		l.output(terror, 3, "", H{}, v...)
-	} else {
-		l.output(terror, 3, stack(), H{}, v...)
-	}
 }
 
 func (l *Logger) DebugF(fields H, v ...interface{}) {
-	if PROD {
+	l.output(Ldebug, 3, fields, v...)
-		l.output(tdebug, 3, "", fields, v...)
-	} else {
-		l.output(tdebug, 3, stack(), fields, v...)
-	}
 }
 
 func (l *Logger) Debug(v ...interface{}) {
-	if PROD {
+	l.output(Ldebug, 3, H{}, v...)
-		l.output(tdebug, 3, "", H{}, v...)
-	} else {
-		l.output(tdebug, 3, stack(), 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...)
 }

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")
+	l.SetErrOutput(io.Discard)
+	l.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)
+	}
+}

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(Lerror, 3, fields, v...)
-		std.output(terror, 3, "", fields, v...)
-	} else {
-		std.output(terror, 3, stack(), fields, v...)
-	}
 }
 
 func Error(v ...interface{}) {
-	if PROD {
+	std.output(Lerror, 3, H{}, v...)
-		std.output(terror, 3, "", H{}, v...)
-	} else {
-		std.output(terror, 3, stack(), H{}, v...)
-	}
 }
 
 func DebugF(fields H, v ...interface{}) {
-	if PROD {
+	std.output(Ldebug, 3, fields, v...)
-		std.output(tdebug, 3, "", fields, v...)
-	} else {
-		std.output(tdebug, 3, stack(), fields, v...)
-	}
 }
 
 func Debug(v ...interface{}) {
-	if PROD {
+	std.output(Ldebug, 3, H{}, v...)
-		std.output(tdebug, 3, "", H{}, v...)
-	} else {
-		std.output(tdebug, 3, stack(), 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...)
 }

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
-}