From 64b4fbcef17a5163bbf8351442b830f19a918f29 Mon Sep 17 00:00:00 2001 From: Evan Phoenix Date: Tue, 5 Mar 2024 15:10:32 -0800 Subject: [PATCH 1/2] Begin v2 of the API, fixes memory usage --- context.go | 2 +- global.go | 2 +- interceptlogger.go | 28 +++++------ intlogger.go | 23 +++++---- logger.go | 16 ++++--- logger_test.go | 4 +- memory_test.go | 27 +++++++++++ nulllogger.go | 9 ++-- record.go | 22 +++++++++ stdlog.go | 2 +- stdlog_test.go | 2 +- value.go | 113 +++++++++++++++++++++++++++++++++++++++++++++ 12 files changed, 211 insertions(+), 39 deletions(-) create mode 100644 memory_test.go create mode 100644 record.go create mode 100644 value.go diff --git a/context.go b/context.go index eb5aba5..8dada6c 100644 --- a/context.go +++ b/context.go @@ -27,7 +27,7 @@ func WithContext(ctx context.Context, logger Logger, args ...interface{}) contex // this will never return a nil value. func FromContext(ctx context.Context) Logger { logger, _ := ctx.Value(contextKey).(Logger) - if logger == nil { + if logger.impl == nil { return L() } diff --git a/global.go b/global.go index a7403f5..30393ba 100644 --- a/global.go +++ b/global.go @@ -36,7 +36,7 @@ func Default() Logger { protect.Do(func() { // If SetDefault was used before Default() was called, we need to // detect that here. - if def == nil { + if def.impl == nil { def = New(DefaultOptions) } }) diff --git a/interceptlogger.go b/interceptlogger.go index e9b1c18..5b75d72 100644 --- a/interceptlogger.go +++ b/interceptlogger.go @@ -10,10 +10,10 @@ import ( "sync/atomic" ) -var _ Logger = &interceptLogger{} +var _ LogImpl = &interceptLogger{} type interceptLogger struct { - Logger + LogImpl mu *sync.Mutex sinkCount *int32 @@ -24,10 +24,10 @@ func NewInterceptLogger(opts *LoggerOptions) InterceptLogger { l := newLogger(opts) if l.callerOffset > 0 { // extra frames for interceptLogger.{Warn,Info,Log,etc...}, and interceptLogger.log - l.callerOffset += 2 + l.callerOffset += 0 } intercept := &interceptLogger{ - Logger: l, + LogImpl: l, mu: new(sync.Mutex), sinkCount: new(int32), Sinks: make(map[SinkAdapter]struct{}), @@ -47,7 +47,7 @@ func (i *interceptLogger) Log(level Level, msg string, args ...interface{}) { // depth. By having all the methods call the same helper we ensure the stack // frame depth is the same. func (i *interceptLogger) log(level Level, msg string, args ...interface{}) { - i.Logger.Log(level, msg, args...) + i.LogImpl.Log(level, msg, args...) if atomic.LoadInt32(i.sinkCount) == 0 { return } @@ -85,7 +85,7 @@ func (i *interceptLogger) Error(msg string, args ...interface{}) { } func (i *interceptLogger) retrieveImplied(args ...interface{}) []interface{} { - top := i.Logger.ImpliedArgs() + top := i.LogImpl.ImpliedArgs() cp := make([]interface{}, len(top)+len(args)) copy(cp, top) @@ -97,7 +97,7 @@ func (i *interceptLogger) retrieveImplied(args ...interface{}) []interface{} { // Create a new sub-Logger that a name descending from the current name. // This is used to create a subsystem specific Logger. // Registered sinks will subscribe to these messages as well. -func (i *interceptLogger) Named(name string) Logger { +func (i *interceptLogger) Named(name string) LogImpl { return i.NamedIntercept(name) } @@ -105,7 +105,7 @@ func (i *interceptLogger) Named(name string) Logger { // name. This is used to create a standalone logger that doesn't fall // within the normal hierarchy. Registered sinks will subscribe // to these messages as well. -func (i *interceptLogger) ResetNamed(name string) Logger { +func (i *interceptLogger) ResetNamed(name string) LogImpl { return i.ResetNamedIntercept(name) } @@ -116,7 +116,7 @@ func (i *interceptLogger) NamedIntercept(name string) InterceptLogger { var sub interceptLogger sub = *i - sub.Logger = i.Logger.Named(name) + sub.LogImpl = i.LogImpl.Named(name) return &sub } @@ -128,19 +128,19 @@ func (i *interceptLogger) ResetNamedIntercept(name string) InterceptLogger { var sub interceptLogger sub = *i - sub.Logger = i.Logger.ResetNamed(name) + sub.LogImpl = i.LogImpl.ResetNamed(name) return &sub } // Return a sub-Logger for which every emitted log message will contain // the given key/value pairs. This is used to create a context specific // Logger. -func (i *interceptLogger) With(args ...interface{}) Logger { +func (i *interceptLogger) With(args ...interface{}) LogImpl { var sub interceptLogger sub = *i - sub.Logger = i.Logger.With(args...) + sub.LogImpl = i.LogImpl.With(args...) return &sub } @@ -191,7 +191,7 @@ func (i *interceptLogger) StandardWriter(opts *StandardLoggerOptions) io.Writer } func (i *interceptLogger) ResetOutput(opts *LoggerOptions) error { - if or, ok := i.Logger.(OutputResettable); ok { + if or, ok := i.LogImpl.(OutputResettable); ok { return or.ResetOutput(opts) } else { return nil @@ -199,7 +199,7 @@ func (i *interceptLogger) ResetOutput(opts *LoggerOptions) error { } func (i *interceptLogger) ResetOutputWithFlush(opts *LoggerOptions, flushable Flushable) error { - if or, ok := i.Logger.(OutputResettable); ok { + if or, ok := i.LogImpl.(OutputResettable); ok { return or.ResetOutputWithFlush(opts, flushable) } else { return nil diff --git a/intlogger.go b/intlogger.go index 104d82f..b36d9c6 100644 --- a/intlogger.go +++ b/intlogger.go @@ -75,7 +75,7 @@ func init() { } // Make sure that intLogger is a Logger -var _ Logger = &intLogger{} +var _ LogImpl = &intLogger{} // intLogger is an internal logger implementation. Internal in that it is // defined entirely by this package. @@ -117,12 +117,14 @@ type intLogger struct { independentLevels bool syncParentLevel bool - subloggerHook func(sub Logger) Logger + subloggerHook func(sub LogImpl) LogImpl } // New returns a configured logger. func New(opts *LoggerOptions) Logger { - return newLogger(opts) + return Logger{ + impl: newLogger(opts), + } } // NewSinkAdapter returns a SinkAdapter with configured settings @@ -213,13 +215,13 @@ func newLogger(opts *LoggerOptions) *intLogger { return l } -func identityHook(logger Logger) Logger { +func identityHook(logger LogImpl) LogImpl { return logger } // offsetIntLogger is the stack frame offset in the call stack for the caller to // one of the Warn, Info, Log, etc methods. -const offsetIntLogger = 3 +const offsetIntLogger = 4 // Log a message and a set of key/value pairs if the given level is at // or more severe that the threshold configured in the Logger. @@ -721,6 +723,11 @@ func (l *intLogger) Log(level Level, msg string, args ...interface{}) { l.log(l.Name(), level, msg, args...) } +// Emit the message and args at the provided level +func (l *intLogger) LogRecord(r Record) { + l.log(l.Name(), r.Level, r.Msg, r.Args...) +} + // Emit the message and args at DEBUG level func (l *intLogger) Debug(msg string, args ...interface{}) { l.log(l.Name(), Debug, msg, args...) @@ -776,7 +783,7 @@ const MissingKey = "EXTRA_VALUE_AT_END" // Return a sub-Logger for which every emitted log message will contain // the given key/value pairs. This is used to create a context specific // Logger. -func (l *intLogger) With(args ...interface{}) Logger { +func (l *intLogger) With(args ...interface{}) LogImpl { var extra interface{} if len(args)%2 != 0 { @@ -823,7 +830,7 @@ func (l *intLogger) With(args ...interface{}) Logger { // Create a new sub-Logger that a name decending from the current name. // This is used to create a subsystem specific Logger. -func (l *intLogger) Named(name string) Logger { +func (l *intLogger) Named(name string) LogImpl { sl := l.copy() if sl.name != "" { @@ -838,7 +845,7 @@ func (l *intLogger) Named(name string) Logger { // Create a new sub-Logger with an explicit name. This ignores the current // name. This is used to create a standalone logger that doesn't fall // within the normal hierarchy. -func (l *intLogger) ResetNamed(name string) Logger { +func (l *intLogger) ResetNamed(name string) LogImpl { sl := l.copy() sl.name = name diff --git a/logger.go b/logger.go index d7806fb..5e2ef5e 100644 --- a/logger.go +++ b/logger.go @@ -144,14 +144,16 @@ func (l Level) String() string { } } -// Logger describes the interface that must be implemented by all loggers. -type Logger interface { +// LogImpl describes the interface that must be implemented by all loggers. +type LogImpl interface { // Args are alternating key, val pairs // keys must be strings // vals can be any type, but display is implementation specific // Emit a message and key/value pairs at a provided log level Log(level Level, msg string, args ...interface{}) + LogRecord(Record) + // Emit a message and key/value pairs at the TRACE level Trace(msg string, args ...interface{}) @@ -187,7 +189,7 @@ type Logger interface { ImpliedArgs() []interface{} // Creates a sublogger that will always have the given key/value pairs - With(args ...interface{}) Logger + With(args ...interface{}) LogImpl // Returns the Name of the logger Name() string @@ -196,12 +198,12 @@ type Logger interface { // If the logger already has a name, the new value will be appended to the current // name. That way, a major subsystem can use this to decorate all it's own logs // without losing context. - Named(name string) Logger + Named(name string) LogImpl // Create a logger that will prepend the name string on the front of all messages. // This sets the name of the logger to the value directly, unlike Named which honor // the current name as well. - ResetNamed(name string) Logger + ResetNamed(name string) LogImpl // Updates the level. This should affect all related loggers as well, // unless they were created with IndependentLevels. If an @@ -327,7 +329,7 @@ type LoggerOptions struct { // the newly created Logger and the returned Logger is returned from the // original function. This option allows customization via interception and // wrapping of Logger instances. - SubloggerHook func(sub Logger) Logger + SubloggerHook func(sub LogImpl) LogImpl } // InterceptLogger describes the interface for using a logger @@ -337,7 +339,7 @@ type LoggerOptions struct { // at a higher one. type InterceptLogger interface { // Logger is the root logger for an InterceptLogger - Logger + LogImpl // RegisterSink adds a SinkAdapter to the InterceptLogger RegisterSink(sink SinkAdapter) diff --git a/logger_test.go b/logger_test.go index dea7013..36b2844 100644 --- a/logger_test.go +++ b/logger_test.go @@ -538,7 +538,7 @@ func TestLogger(t *testing.T) { assert.Equal(t, "[INFO] this is test: production=\"12 beans/day\"\n", rest) - logger.(OutputResettable).ResetOutput(&LoggerOptions{ + logger.impl.(OutputResettable).ResetOutput(&LoggerOptions{ Output: &second, }) @@ -568,7 +568,7 @@ func TestLogger(t *testing.T) { str := first.String() assert.Empty(t, str) - logger.(OutputResettable).ResetOutputWithFlush(&LoggerOptions{ + logger.impl.(OutputResettable).ResetOutputWithFlush(&LoggerOptions{ Output: &second, }, &first) diff --git a/memory_test.go b/memory_test.go new file mode 100644 index 0000000..65f31ae --- /dev/null +++ b/memory_test.go @@ -0,0 +1,27 @@ +package hclog + +import ( + "bytes" + "testing" +) + +func BenchmarkLoggerMemory(b *testing.B) { + var buf bytes.Buffer + + logger := New(&LoggerOptions{ + Name: "test", + Output: &buf, + Level: Info, + }) + + for i := 0; i < b.N; i++ { + logger.Trace("this is some message", + "name", "foo", + "what", "benchmarking yourself", + ) + + if buf.Len() != 0 { + panic("oops") + } + } +} diff --git a/nulllogger.go b/nulllogger.go index d43da80..ddd433d 100644 --- a/nulllogger.go +++ b/nulllogger.go @@ -12,13 +12,14 @@ import ( // NewNullLogger instantiates a Logger for which all calls // will succeed without doing anything. // Useful for testing purposes. -func NewNullLogger() Logger { +func NewNullLogger() LogImpl { return &nullLogger{} } type nullLogger struct{} func (l *nullLogger) Log(level Level, msg string, args ...interface{}) {} +func (l *nullLogger) LogRecord(r Record) {} func (l *nullLogger) Trace(msg string, args ...interface{}) {} @@ -42,13 +43,13 @@ func (l *nullLogger) IsError() bool { return false } func (l *nullLogger) ImpliedArgs() []interface{} { return []interface{}{} } -func (l *nullLogger) With(args ...interface{}) Logger { return l } +func (l *nullLogger) With(args ...interface{}) LogImpl { return l } func (l *nullLogger) Name() string { return "" } -func (l *nullLogger) Named(name string) Logger { return l } +func (l *nullLogger) Named(name string) LogImpl { return l } -func (l *nullLogger) ResetNamed(name string) Logger { return l } +func (l *nullLogger) ResetNamed(name string) LogImpl { return l } func (l *nullLogger) SetLevel(level Level) {} diff --git a/record.go b/record.go new file mode 100644 index 0000000..def50b4 --- /dev/null +++ b/record.go @@ -0,0 +1,22 @@ +package hclog + +const inlineArgs = 10 + +type Record struct { + Level Level + Msg string + CallerPc uintptr + + inline [inlineArgs]interface{} + Args []interface{} +} + +func (r *Record) SetArgs(args []interface{}) { + if len(args) > inlineArgs { + r.Args = make([]interface{}, len(args)) + copy(r.Args, args) + } else { + copy(r.inline[:], args) + r.Args = r.inline[:] + } +} diff --git a/stdlog.go b/stdlog.go index 03739b6..da3a5bc 100644 --- a/stdlog.go +++ b/stdlog.go @@ -18,7 +18,7 @@ var logTimestampRegexp = regexp.MustCompile(`^[\d\s\:\/\.\+-TZ]*`) // and back into our Logger. This is basically the only way to // build upon *log.Logger. type stdlogAdapter struct { - log Logger + log LogImpl inferLevels bool inferLevelsWithTimestamp bool forceLevel Level diff --git a/stdlog_test.go b/stdlog_test.go index b42159f..432c04b 100644 --- a/stdlog_test.go +++ b/stdlog_test.go @@ -206,7 +206,7 @@ func TestStdlogAdapter_ForceLevel(t *testing.T) { }) s := &stdlogAdapter{ - log: logger, + log: logger.impl, forceLevel: c.forceLevel, inferLevels: c.inferLevels, } diff --git a/value.go b/value.go new file mode 100644 index 0000000..5914901 --- /dev/null +++ b/value.go @@ -0,0 +1,113 @@ +package hclog + +import ( + "runtime" +) + +type Logger struct { + impl LogImpl +} + +func (v *Logger) log(level Level, msg string, args ...interface{}) { + if level < v.impl.GetLevel() { + return + } + + var pc uintptr + var pcs [1]uintptr + // skip [runtime.Callers, this function, this function's caller] + runtime.Callers(3, pcs[:]) + pc = pcs[0] + + r := Record{ + Level: level, + Msg: msg, + CallerPc: pc, + } + + r.SetArgs(args) + + v.impl.LogRecord(r) +} + +// Emit the message and args at the given level +func (v *Logger) Log(level Level, msg string, args ...interface{}) { + v.log(level, msg, args...) +} + +// Emit the message and args at TRACE level +func (v *Logger) Trace(msg string, args ...interface{}) { + v.log(Trace, msg, args...) +} + +// Emit the message and args at DEBUG level +func (v *Logger) Debug(msg string, args ...interface{}) { + v.log(Debug, msg, args...) +} + +// Emit the message and args at INFO level +func (v *Logger) Info(msg string, args ...interface{}) { + v.log(Info, msg, args...) +} + +// Emit the message and args at WARN level +func (v *Logger) Warn(msg string, args ...interface{}) { + v.log(Warn, msg, args...) +} + +// Emit the message and args at ERROR level +func (v Logger) Error(msg string, args ...interface{}) { + v.log(Error, msg, args...) +} + +func (v Logger) IsTrace() bool { + return Debug >= v.impl.GetLevel() +} + +func (v Logger) IsDebug() bool { + return Debug >= v.impl.GetLevel() +} + +func (v Logger) IsInfo() bool { + return Debug >= v.impl.GetLevel() +} + +func (v Logger) IsWarn() bool { + return Debug >= v.impl.GetLevel() +} + +func (v Logger) IsError() bool { + return Debug >= v.impl.GetLevel() +} + +func (v Logger) Named(name string) Logger { + return Logger{ + v.impl.Named(name), + } +} + +func (v Logger) ResetNamed(name string) Logger { + return Logger{ + v.impl.ResetNamed(name), + } +} + +func (v Logger) With(args ...interface{}) Logger { + return Logger{ + v.impl.With(args...), + } +} + +func (v *Logger) SetLevel(level Level) { + v.impl.SetLevel(level) +} + +func (v *Logger) GetLevel() Level { + return v.impl.GetLevel() +} + +func AsValue(log LogImpl) Logger { + return Logger{ + impl: log, + } +} From fb7680a22c01404cbc1ad68ff1cf1e6483f14363 Mon Sep 17 00:00:00 2001 From: Evan Phoenix Date: Tue, 5 Mar 2024 15:39:09 -0800 Subject: [PATCH 2/2] Add test for allocations --- memory_test.go | 25 +++++++++++++++++++++++++ 1 file changed, 25 insertions(+) diff --git a/memory_test.go b/memory_test.go index 65f31ae..3e8f864 100644 --- a/memory_test.go +++ b/memory_test.go @@ -25,3 +25,28 @@ func BenchmarkLoggerMemory(b *testing.B) { } } } + +func TestLoggerMemory(t *testing.T) { + var buf bytes.Buffer + + logger := New(&LoggerOptions{ + Name: "test", + Output: &buf, + Level: Info, + }) + + avg := testing.AllocsPerRun(100, func() { + logger.Trace("this is some message", + "name", "foo", + "what", "benchmarking yourself", + ) + + if buf.Len() != 0 { + panic("oops") + } + }) + + if avg != 0 { + t.Fatalf("ignored logs allocated") + } +}