From 69df0d2ed71e288309a424ac82040635d7e29731 Mon Sep 17 00:00:00 2001 From: plan Date: Sat, 18 Jun 2016 21:47:44 +0800 Subject: [PATCH 1/5] Use Buffer pool to allocate bytes.Buffer for formatter Entry.Reader() seams not necessary, removed --- entry.go | 51 ++++++++++++++++++++++++++++------------------- text_formatter.go | 8 ++++++-- 2 files changed, 37 insertions(+), 22 deletions(-) diff --git a/entry.go b/entry.go index 54bfc57..4edbe7a 100644 --- a/entry.go +++ b/entry.go @@ -3,11 +3,21 @@ package logrus import ( "bytes" "fmt" - "io" "os" + "sync" "time" ) +var bufferPool *sync.Pool + +func init() { + bufferPool = &sync.Pool{ + New: func() interface{} { + return new(bytes.Buffer) + }, + } +} + // Defines the key when adding errors using WithError. var ErrorKey = "error" @@ -29,6 +39,9 @@ type Entry struct { // Message passed to Debug, Info, Warn, Error, Fatal or Panic Message string + + // When formatter is called in entry.log(), an Buffer may be set to entry + Buffer *bytes.Buffer } func NewEntry(logger *Logger) *Entry { @@ -39,21 +52,15 @@ func NewEntry(logger *Logger) *Entry { } } -// Returns a reader for the entry, which is a proxy to the formatter. -func (entry *Entry) Reader() (*bytes.Buffer, error) { - serialized, err := entry.Logger.Formatter.Format(entry) - return bytes.NewBuffer(serialized), err -} - // Returns the string representation from the reader and ultimately the // formatter. func (entry *Entry) String() (string, error) { - reader, err := entry.Reader() + serialized, err := entry.Logger.Formatter.Format(entry) if err != nil { return "", err } - - return reader.String(), err + str := string(serialized) + return str, nil } // Add an error as single field (using the key defined in ErrorKey) to the Entry. @@ -81,6 +88,7 @@ func (entry *Entry) WithFields(fields Fields) *Entry { // This function is not declared with a pointer value because otherwise // race conditions will occur when using multiple goroutines func (entry Entry) log(level Level, msg string) { + var buffer *bytes.Buffer entry.Time = time.Now() entry.Level = level entry.Message = msg @@ -90,20 +98,23 @@ func (entry Entry) log(level Level, msg string) { fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err) entry.Logger.mu.Unlock() } - - reader, err := entry.Reader() + buffer = bufferPool.Get().(*bytes.Buffer) + buffer.Reset() + defer bufferPool.Put(buffer) + entry.Buffer = buffer + serialized, err := entry.Logger.Formatter.Format(&entry) + entry.Buffer = nil if err != nil { entry.Logger.mu.Lock() fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err) entry.Logger.mu.Unlock() - } - - entry.Logger.mu.Lock() - defer entry.Logger.mu.Unlock() - - _, err = io.Copy(entry.Logger.Out, reader) - if err != nil { - fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err) + } else { + entry.Logger.mu.Lock() + _, err = entry.Logger.Out.Write(serialized) + if err != nil { + fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err) + } + entry.Logger.mu.Unlock() } // To avoid Entry#log() returning a value that only would make sense for diff --git a/text_formatter.go b/text_formatter.go index 6afd0e0..cce61f2 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -57,6 +57,7 @@ type TextFormatter struct { } func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { + var b *bytes.Buffer var keys []string = make([]string, 0, len(entry.Data)) for k := range entry.Data { keys = append(keys, k) @@ -65,8 +66,11 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { if !f.DisableSorting { sort.Strings(keys) } - - b := &bytes.Buffer{} + if entry.Buffer != nil { + b = entry.Buffer + } else { + b = &bytes.Buffer{} + } prefixFieldClashes(entry.Data) From cb2bda2c54ef6b2cb42e5f5e30bc7420ae40ab11 Mon Sep 17 00:00:00 2001 From: plan Date: Sat, 18 Jun 2016 22:20:51 +0800 Subject: [PATCH 2/5] Add benchmark for logger --- logger_bench_test.go | 37 +++++++++++++++++++++++++++++++++++++ 1 file changed, 37 insertions(+) create mode 100644 logger_bench_test.go diff --git a/logger_bench_test.go b/logger_bench_test.go new file mode 100644 index 0000000..28a1a26 --- /dev/null +++ b/logger_bench_test.go @@ -0,0 +1,37 @@ +package logrus + +import ( + "os" + "testing" +) + +// smallFields is a small size data set for benchmarking +var loggerFields = Fields{ + "foo": "bar", + "baz": "qux", + "one": "two", + "three": "four", +} + +func BenchmarkDummyLogger(b *testing.B) { + nullf, err := os.OpenFile("/dev/null", os.O_WRONLY, 0666) + if err != nil { + b.Fatalf("%v", err) + } + defer nullf.Close() + doLoggerBenchmark(b, nullf, &TextFormatter{DisableColors: true}, smallFields) +} + +func doLoggerBenchmark(b *testing.B, out *os.File, formatter Formatter, fields Fields) { + logger := Logger{ + Out: out, + Level: InfoLevel, + Formatter: formatter, + } + entry := logger.WithFields(fields) + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + entry.Info("aaa") + } + }) +} From bc35b026f0f9469fbd784f9066e936722d144c27 Mon Sep 17 00:00:00 2001 From: plan Date: Sun, 19 Jun 2016 03:21:15 +0800 Subject: [PATCH 3/5] Provide logger.SetNoLock() to remove locking during log output Locking is enabled by default. When file is opened with appending mode, it's safe to write concurrently to a file. In this case user can choose to disable the lock. --- logger.go | 32 ++++++++++++++++++++++++++++++-- logger_bench_test.go | 24 ++++++++++++++++++++++++ 2 files changed, 54 insertions(+), 2 deletions(-) diff --git a/logger.go b/logger.go index 9052a80..f3b6438 100644 --- a/logger.go +++ b/logger.go @@ -26,8 +26,29 @@ type Logger struct { // to) `logrus.Info`, which allows Info(), Warn(), Error() and Fatal() to be // logged. `logrus.Debug` is useful in Level Level - // Used to sync writing to the log. - mu sync.Mutex + // Used to sync writing to the log. Locking is enabled by Default + mu MutexWrap +} + +type MutexWrap struct { + lock sync.Mutex + disabled bool +} + +func (mw *MutexWrap) Lock() { + if !mw.disabled { + mw.lock.Lock() + } +} + +func (mw *MutexWrap) Unlock() { + if !mw.disabled { + mw.lock.Unlock() + } +} + +func (mw *MutexWrap) Disable() { + mw.disabled = true } // Creates a new logger. Configuration should be set by changing `Formatter`, @@ -210,3 +231,10 @@ func (logger *Logger) Panicln(args ...interface{}) { NewEntry(logger).Panicln(args...) } } + +//When file is opened with appending mode, it's safe to +//write concurrently to a file (within 4k message on Linux). +//In these cases user can choose to disable the lock. +func (logger *Logger) SetNoLock() { + logger.mu.Disable() +} diff --git a/logger_bench_test.go b/logger_bench_test.go index 28a1a26..dd23a35 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -22,6 +22,15 @@ func BenchmarkDummyLogger(b *testing.B) { doLoggerBenchmark(b, nullf, &TextFormatter{DisableColors: true}, smallFields) } +func BenchmarkDummyLoggerNoLock(b *testing.B) { + nullf, err := os.OpenFile("/dev/null", os.O_WRONLY|os.O_APPEND, 0666) + if err != nil { + b.Fatalf("%v", err) + } + defer nullf.Close() + doLoggerBenchmarkNoLock(b, nullf, &TextFormatter{DisableColors: true}, smallFields) +} + func doLoggerBenchmark(b *testing.B, out *os.File, formatter Formatter, fields Fields) { logger := Logger{ Out: out, @@ -35,3 +44,18 @@ func doLoggerBenchmark(b *testing.B, out *os.File, formatter Formatter, fields F } }) } + +func doLoggerBenchmarkNoLock(b *testing.B, out *os.File, formatter Formatter, fields Fields) { + logger := Logger{ + Out: out, + Level: InfoLevel, + Formatter: formatter, + } + logger.SetNoLock() + entry := logger.WithFields(fields) + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + entry.Info("aaa") + } + }) +} From 4c4ffbea1705e6a13ae08bf7904302ebb864ea6b Mon Sep 17 00:00:00 2001 From: plan Date: Thu, 11 Aug 2016 01:39:36 +0800 Subject: [PATCH 4/5] Add document for logger.SetNoLock() --- README.md | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/README.md b/README.md index f8302c3..8ee3f96 100644 --- a/README.md +++ b/README.md @@ -400,3 +400,20 @@ handler := func() { logrus.RegisterExitHandler(handler) ... ``` + +#### Thread safty + +By default Logger is protected by mutex for concurrent writes, this mutex is invoked when calling hooks and writing logs. +If you are sure such locking is not needed, you can call logger.SetNoLock() to disable the locking. + +Situation when locking is not needed includes: + +* You have no hooks registered, or hooks calling is already thread-safe. + +* Writing to logger.Out is already thread-safe, for example: + + 1) logger.Out is protected by locks. + + 2) logger.Out is a os.File handler opened with `O_APPEND` flag, and every write is smaller than 4k. (This allow multi-thread/multi-process writing) + + (Refer to http://www.notthewizard.com/2014/06/17/are-files-appends-really-atomic/) From 53cbb9dc6df4a5ae2a1c85ff3a265b832d7667db Mon Sep 17 00:00:00 2001 From: plan Date: Sun, 19 Jun 2016 04:08:25 +0800 Subject: [PATCH 5/5] Reuse entry from the same logger --- logger.go | 122 ++++++++++++++++++++++++++++++++++++++++++------------ 1 file changed, 95 insertions(+), 27 deletions(-) diff --git a/logger.go b/logger.go index f3b6438..b769f3d 100644 --- a/logger.go +++ b/logger.go @@ -28,6 +28,8 @@ type Logger struct { Level Level // Used to sync writing to the log. Locking is enabled by Default mu MutexWrap + // Reusable empty entry + entryPool sync.Pool } type MutexWrap struct { @@ -72,163 +74,229 @@ func New() *Logger { } } +func (logger *Logger) newEntry() *Entry { + entry, ok := logger.entryPool.Get().(*Entry) + if ok { + return entry + } + return NewEntry(logger) +} + +func (logger *Logger) releaseEntry(entry *Entry) { + logger.entryPool.Put(entry) +} + // Adds a field to the log entry, note that it doesn't log until you call // Debug, Print, Info, Warn, Fatal or Panic. It only creates a log entry. // If you want multiple fields, use `WithFields`. func (logger *Logger) WithField(key string, value interface{}) *Entry { - return NewEntry(logger).WithField(key, value) + entry := logger.newEntry() + defer logger.releaseEntry(entry) + return entry.WithField(key, value) } // Adds a struct of fields to the log entry. All it does is call `WithField` for // each `Field`. func (logger *Logger) WithFields(fields Fields) *Entry { - return NewEntry(logger).WithFields(fields) + entry := logger.newEntry() + defer logger.releaseEntry(entry) + return entry.WithFields(fields) } // Add an error as single field to the log entry. All it does is call // `WithError` for the given `error`. func (logger *Logger) WithError(err error) *Entry { - return NewEntry(logger).WithError(err) + entry := logger.newEntry() + defer logger.releaseEntry(entry) + return entry.WithError(err) } func (logger *Logger) Debugf(format string, args ...interface{}) { if logger.Level >= DebugLevel { - NewEntry(logger).Debugf(format, args...) + entry := logger.newEntry() + entry.Debugf(format, args...) + logger.releaseEntry(entry) } } func (logger *Logger) Infof(format string, args ...interface{}) { if logger.Level >= InfoLevel { - NewEntry(logger).Infof(format, args...) + entry := logger.newEntry() + entry.Infof(format, args...) + logger.releaseEntry(entry) } } func (logger *Logger) Printf(format string, args ...interface{}) { - NewEntry(logger).Printf(format, args...) + entry := logger.newEntry() + entry.Printf(format, args...) + logger.releaseEntry(entry) } func (logger *Logger) Warnf(format string, args ...interface{}) { if logger.Level >= WarnLevel { - NewEntry(logger).Warnf(format, args...) + entry := logger.newEntry() + entry.Warnf(format, args...) + logger.releaseEntry(entry) } } func (logger *Logger) Warningf(format string, args ...interface{}) { if logger.Level >= WarnLevel { - NewEntry(logger).Warnf(format, args...) + entry := logger.newEntry() + entry.Warnf(format, args...) + logger.releaseEntry(entry) } } func (logger *Logger) Errorf(format string, args ...interface{}) { if logger.Level >= ErrorLevel { - NewEntry(logger).Errorf(format, args...) + entry := logger.newEntry() + entry.Errorf(format, args...) + logger.releaseEntry(entry) } } func (logger *Logger) Fatalf(format string, args ...interface{}) { if logger.Level >= FatalLevel { - NewEntry(logger).Fatalf(format, args...) + entry := logger.newEntry() + entry.Fatalf(format, args...) + logger.releaseEntry(entry) } Exit(1) } func (logger *Logger) Panicf(format string, args ...interface{}) { if logger.Level >= PanicLevel { - NewEntry(logger).Panicf(format, args...) + entry := logger.newEntry() + entry.Panicf(format, args...) + logger.releaseEntry(entry) } } func (logger *Logger) Debug(args ...interface{}) { if logger.Level >= DebugLevel { - NewEntry(logger).Debug(args...) + entry := logger.newEntry() + entry.Debug(args...) + logger.releaseEntry(entry) } } func (logger *Logger) Info(args ...interface{}) { if logger.Level >= InfoLevel { - NewEntry(logger).Info(args...) + entry := logger.newEntry() + entry.Info(args...) + logger.releaseEntry(entry) } } func (logger *Logger) Print(args ...interface{}) { - NewEntry(logger).Info(args...) + entry := logger.newEntry() + entry.Info(args...) + logger.releaseEntry(entry) } func (logger *Logger) Warn(args ...interface{}) { if logger.Level >= WarnLevel { - NewEntry(logger).Warn(args...) + entry := logger.newEntry() + entry.Warn(args...) + logger.releaseEntry(entry) } } func (logger *Logger) Warning(args ...interface{}) { if logger.Level >= WarnLevel { - NewEntry(logger).Warn(args...) + entry := logger.newEntry() + entry.Warn(args...) + logger.releaseEntry(entry) } } func (logger *Logger) Error(args ...interface{}) { if logger.Level >= ErrorLevel { - NewEntry(logger).Error(args...) + entry := logger.newEntry() + entry.Error(args...) + logger.releaseEntry(entry) } } func (logger *Logger) Fatal(args ...interface{}) { if logger.Level >= FatalLevel { - NewEntry(logger).Fatal(args...) + entry := logger.newEntry() + entry.Fatal(args...) + logger.releaseEntry(entry) } Exit(1) } func (logger *Logger) Panic(args ...interface{}) { if logger.Level >= PanicLevel { - NewEntry(logger).Panic(args...) + entry := logger.newEntry() + entry.Panic(args...) + logger.releaseEntry(entry) } } func (logger *Logger) Debugln(args ...interface{}) { if logger.Level >= DebugLevel { - NewEntry(logger).Debugln(args...) + entry := logger.newEntry() + entry.Debugln(args...) + logger.releaseEntry(entry) } } func (logger *Logger) Infoln(args ...interface{}) { if logger.Level >= InfoLevel { - NewEntry(logger).Infoln(args...) + entry := logger.newEntry() + entry.Infoln(args...) + logger.releaseEntry(entry) } } func (logger *Logger) Println(args ...interface{}) { - NewEntry(logger).Println(args...) + entry := logger.newEntry() + entry.Println(args...) + logger.releaseEntry(entry) } func (logger *Logger) Warnln(args ...interface{}) { if logger.Level >= WarnLevel { - NewEntry(logger).Warnln(args...) + entry := logger.newEntry() + entry.Warnln(args...) + logger.releaseEntry(entry) } } func (logger *Logger) Warningln(args ...interface{}) { if logger.Level >= WarnLevel { - NewEntry(logger).Warnln(args...) + entry := logger.newEntry() + entry.Warnln(args...) + logger.releaseEntry(entry) } } func (logger *Logger) Errorln(args ...interface{}) { if logger.Level >= ErrorLevel { - NewEntry(logger).Errorln(args...) + entry := logger.newEntry() + entry.Errorln(args...) + logger.releaseEntry(entry) } } func (logger *Logger) Fatalln(args ...interface{}) { if logger.Level >= FatalLevel { - NewEntry(logger).Fatalln(args...) + entry := logger.newEntry() + entry.Fatalln(args...) + logger.releaseEntry(entry) } Exit(1) } func (logger *Logger) Panicln(args ...interface{}) { if logger.Level >= PanicLevel { - NewEntry(logger).Panicln(args...) + entry := logger.newEntry() + entry.Panicln(args...) + logger.releaseEntry(entry) } }