diff --git a/.changes/unreleased/ENHANCEMENTS-20230418-201952.yaml b/.changes/unreleased/ENHANCEMENTS-20230418-201952.yaml new file mode 100644 index 0000000..5c549be --- /dev/null +++ b/.changes/unreleased/ENHANCEMENTS-20230418-201952.yaml @@ -0,0 +1,6 @@ +kind: ENHANCEMENTS +body: 'tfsdklog: Improved logging performance 20x when logs would be skipped due to + logging level' +time: 2023-04-18T20:19:52.460485-04:00 +custom: + Issue: "149" diff --git a/tfsdklog/levels.go b/tfsdklog/levels.go new file mode 100644 index 0000000..ed475a1 --- /dev/null +++ b/tfsdklog/levels.go @@ -0,0 +1,81 @@ +package tfsdklog + +import ( + "sync" + + "github.com/hashicorp/go-hclog" +) + +var ( + // rootLevel stores the effective level of the root SDK logger during + // NewRootSDKLogger where the value is deterministically chosen based on + // environment variables, etc. This call generally happens with each new + // provider RPC request. If the environment variable values changed during + // runtime between calls, then inflight provider requests checking this + // value would receive the most up-to-date value which would potentially + // differ with the actual in-context logger level. This tradeoff would only + // effect the inflight requests and should not be an overall performance + // concern in the case of this level causing more context checks until the + // request is over. + rootLevel hclog.Level = hclog.NoLevel + + // rootLevelMutex is a read-write mutex that protects rootLevel from + // triggering the data race detector. + rootLevelMutex = sync.RWMutex{} + + // subsystemLevels stores the effective level of all subsystem SDK loggers + // during NewSubsystem where the value is deterministically chosen based on + // environment variables, etc. This call generally happens with each new + // provider RPC request. If the environment variable values changed during + // runtime between calls, then inflight provider requests checking this + // value would receive the most up-to-date value which would potentially + // differ with the actual in-context logger level. This tradeoff would only + // effect the inflight requests and should not be an overall performance + // concern in the case of this level causing more context checks until the + // request is over. + subsystemLevels map[string]hclog.Level = make(map[string]hclog.Level) + + // subsystemLevelsMutex is a read-write mutex that protects the + // subsystemLevels map from concurrent read and write panics. + subsystemLevelsMutex = sync.RWMutex{} +) + +// subsystemWouldLog returns true if the subsystem SDK logger would emit a log +// at the given level. This is performed outside the context-based logger for +// performance. +func subsystemWouldLog(subsystem string, level hclog.Level) bool { + subsystemLevelsMutex.RLock() + + setLevel, ok := subsystemLevels[subsystem] + + subsystemLevelsMutex.RUnlock() + + if !ok { + return false + } + + return wouldLog(setLevel, level) +} + +// rootWouldLog returns true if the root SDK logger would emit a log at the +// given level. This is performed outside the context-based logger for +// performance. +func rootWouldLog(level hclog.Level) bool { + rootLevelMutex.RLock() + + setLevel := rootLevel + + rootLevelMutex.RUnlock() + + return wouldLog(setLevel, level) +} + +// wouldLog returns true if the set level would emit a log at the given +// level. This is performed outside the context-based logger for performance. +func wouldLog(setLevel, checkLevel hclog.Level) bool { + if checkLevel == hclog.Off { + return false + } + + return checkLevel >= setLevel +} diff --git a/tfsdklog/levels_test.go b/tfsdklog/levels_test.go new file mode 100644 index 0000000..6a45fa8 --- /dev/null +++ b/tfsdklog/levels_test.go @@ -0,0 +1,331 @@ +package tfsdklog + +import ( + "testing" + + "github.com/google/go-cmp/cmp" + "github.com/hashicorp/go-hclog" +) + +func TestRootWouldLog(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + rootLevel hclog.Level + checkLevel hclog.Level + expected bool + }{ + "true": { + rootLevel: hclog.Trace, + checkLevel: hclog.Debug, + expected: true, + }, + "false": { + rootLevel: hclog.Warn, + checkLevel: hclog.Debug, + expected: false, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + rootLevelMutex.Lock() + + rootLevel = testCase.rootLevel + + rootLevelMutex.Unlock() + + got := rootWouldLog(testCase.checkLevel) + + if diff := cmp.Diff(got, testCase.expected); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } + }) + } +} + +func TestSubsystemWouldLog(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + subsystemLevel hclog.Level + checkLevel hclog.Level + expected bool + }{ + "true": { + subsystemLevel: hclog.Trace, + checkLevel: hclog.Debug, + expected: true, + }, + "false": { + subsystemLevel: hclog.Warn, + checkLevel: hclog.Debug, + expected: false, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + subsystemLevelsMutex.Lock() + + subsystemLevels[t.Name()] = testCase.subsystemLevel + + subsystemLevelsMutex.Unlock() + + got := subsystemWouldLog(t.Name(), testCase.checkLevel) + + subsystemLevelsMutex.Lock() + + delete(subsystemLevels, t.Name()) + + subsystemLevelsMutex.Unlock() + + if diff := cmp.Diff(got, testCase.expected); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } + }) + } +} + +func TestWouldLog(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + setLevel hclog.Level + checkLevel hclog.Level + expected bool + }{ + "nolevel-nolevel": { + setLevel: hclog.NoLevel, + checkLevel: hclog.NoLevel, + expected: true, + }, + "nolevel-trace": { + setLevel: hclog.NoLevel, + checkLevel: hclog.Trace, + expected: true, + }, + "nolevel-debug": { + setLevel: hclog.NoLevel, + checkLevel: hclog.Debug, + expected: true, + }, + "nolevel-info": { + setLevel: hclog.NoLevel, + checkLevel: hclog.Info, + expected: true, + }, + "nolevel-warn": { + setLevel: hclog.NoLevel, + checkLevel: hclog.Warn, + expected: true, + }, + "nolevel-error": { + setLevel: hclog.NoLevel, + checkLevel: hclog.Error, + expected: true, + }, + "nolevel-off": { + setLevel: hclog.NoLevel, + checkLevel: hclog.Off, + expected: false, + }, + "trace-nolevel": { + setLevel: hclog.Trace, + checkLevel: hclog.NoLevel, + expected: false, + }, + "trace-trace": { + setLevel: hclog.Trace, + checkLevel: hclog.Trace, + expected: true, + }, + "trace-debug": { + setLevel: hclog.Trace, + checkLevel: hclog.Debug, + expected: true, + }, + "trace-info": { + setLevel: hclog.Trace, + checkLevel: hclog.Info, + expected: true, + }, + "trace-warn": { + setLevel: hclog.Trace, + checkLevel: hclog.Warn, + expected: true, + }, + "trace-error": { + setLevel: hclog.Trace, + checkLevel: hclog.Error, + expected: true, + }, + "trace-off": { + setLevel: hclog.Trace, + checkLevel: hclog.Off, + expected: false, + }, + "debug-nolevel": { + setLevel: hclog.Trace, + checkLevel: hclog.NoLevel, + expected: false, + }, + "debug-trace": { + setLevel: hclog.Debug, + checkLevel: hclog.Trace, + expected: false, + }, + "debug-debug": { + setLevel: hclog.Debug, + checkLevel: hclog.Debug, + expected: true, + }, + "debug-info": { + setLevel: hclog.Debug, + checkLevel: hclog.Info, + expected: true, + }, + "debug-warn": { + setLevel: hclog.Debug, + checkLevel: hclog.Warn, + expected: true, + }, + "debug-error": { + setLevel: hclog.Debug, + checkLevel: hclog.Error, + expected: true, + }, + "debug-off": { + setLevel: hclog.Debug, + checkLevel: hclog.Off, + expected: false, + }, + "info-nolevel": { + setLevel: hclog.Info, + checkLevel: hclog.NoLevel, + expected: false, + }, + "info-trace": { + setLevel: hclog.Info, + checkLevel: hclog.Trace, + expected: false, + }, + "info-debug": { + setLevel: hclog.Info, + checkLevel: hclog.Debug, + expected: false, + }, + "info-info": { + setLevel: hclog.Info, + checkLevel: hclog.Info, + expected: true, + }, + "info-warn": { + setLevel: hclog.Info, + checkLevel: hclog.Warn, + expected: true, + }, + "info-error": { + setLevel: hclog.Info, + checkLevel: hclog.Error, + expected: true, + }, + "info-off": { + setLevel: hclog.Info, + checkLevel: hclog.Off, + expected: false, + }, + "warn-nolevel": { + setLevel: hclog.Warn, + checkLevel: hclog.NoLevel, + expected: false, + }, + "warn-trace": { + setLevel: hclog.Warn, + checkLevel: hclog.Trace, + expected: false, + }, + "warn-debug": { + setLevel: hclog.Warn, + checkLevel: hclog.Debug, + expected: false, + }, + "warn-info": { + setLevel: hclog.Warn, + checkLevel: hclog.Info, + expected: false, + }, + "warn-warn": { + setLevel: hclog.Warn, + checkLevel: hclog.Warn, + expected: true, + }, + "warn-error": { + setLevel: hclog.Warn, + checkLevel: hclog.Error, + expected: true, + }, + "warn-off": { + setLevel: hclog.Warn, + checkLevel: hclog.Off, + expected: false, + }, + "error-nolevel": { + setLevel: hclog.Error, + checkLevel: hclog.NoLevel, + expected: false, + }, + "error-trace": { + setLevel: hclog.Error, + checkLevel: hclog.Trace, + expected: false, + }, + "error-debug": { + setLevel: hclog.Error, + checkLevel: hclog.Debug, + expected: false, + }, + "error-info": { + setLevel: hclog.Error, + checkLevel: hclog.Info, + expected: false, + }, + "error-warn": { + setLevel: hclog.Error, + checkLevel: hclog.Warn, + expected: false, + }, + "error-error": { + setLevel: hclog.Error, + checkLevel: hclog.Error, + expected: true, + }, + "error-off": { + setLevel: hclog.Error, + checkLevel: hclog.Off, + expected: false, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + got := wouldLog(testCase.setLevel, testCase.checkLevel) + + if diff := cmp.Diff(got, testCase.expected); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } + }) + } +} diff --git a/tfsdklog/sdk.go b/tfsdklog/sdk.go index 2891ddf..4ffb2cc 100644 --- a/tfsdklog/sdk.go +++ b/tfsdklog/sdk.go @@ -35,6 +35,14 @@ func NewRootSDKLogger(ctx context.Context, options ...logging.Option) context.Co if opts.Level == hclog.NoLevel { opts.Level = hclog.Trace } + + // Cache root logger level outside context for performance reasons. + rootLevelMutex.Lock() + + rootLevel = opts.Level + + rootLevelMutex.Unlock() + loggerOptions := &hclog.LoggerOptions{ Name: opts.Name, Level: opts.Level, diff --git a/tfsdklog/subsystem.go b/tfsdklog/subsystem.go index 4d2a1a1..0aeb546 100644 --- a/tfsdklog/subsystem.go +++ b/tfsdklog/subsystem.go @@ -58,6 +58,13 @@ func NewSubsystem(ctx context.Context, subsystem string, options ...logging.Opti subLogger = hclog.New(subLoggerOptions) } + // Cache subsystem logger level outside context for performance reasons. + subsystemLevelsMutex.Lock() + + subsystemLevels[subsystem] = subLoggerTFLoggerOpts.Level + + subsystemLevelsMutex.Unlock() + // Set the configured log level if subLoggerTFLoggerOpts.Level != hclog.NoLevel { subLogger.SetLevel(subLoggerTFLoggerOpts.Level) @@ -97,6 +104,10 @@ func SubsystemSetField(ctx context.Context, subsystem, key string, value interfa // subsystem logger, e.g. by the `SubsystemSetField()` function, and across // multiple maps. func SubsystemTrace(ctx context.Context, subsystem, msg string, additionalFields ...map[string]interface{}) { + if !subsystemWouldLog(subsystem, hclog.Trace) { + return + } + logger := logging.GetSDKSubsystemLogger(ctx, subsystem) if logger == nil { if logging.GetSDKRootLogger(ctx) == nil { @@ -122,6 +133,10 @@ func SubsystemTrace(ctx context.Context, subsystem, msg string, additionalFields // subsystem logger, e.g. by the `SubsystemSetField()` function, and across // multiple maps. func SubsystemDebug(ctx context.Context, subsystem, msg string, additionalFields ...map[string]interface{}) { + if !subsystemWouldLog(subsystem, hclog.Debug) { + return + } + logger := logging.GetSDKSubsystemLogger(ctx, subsystem) if logger == nil { if logging.GetSDKRootLogger(ctx) == nil { @@ -147,6 +162,10 @@ func SubsystemDebug(ctx context.Context, subsystem, msg string, additionalFields // subsystem logger, e.g. by the `SubsystemSetField()` function, and across // multiple maps. func SubsystemInfo(ctx context.Context, subsystem, msg string, additionalFields ...map[string]interface{}) { + if !subsystemWouldLog(subsystem, hclog.Info) { + return + } + logger := logging.GetSDKSubsystemLogger(ctx, subsystem) if logger == nil { if logging.GetSDKRootLogger(ctx) == nil { @@ -172,6 +191,10 @@ func SubsystemInfo(ctx context.Context, subsystem, msg string, additionalFields // subsystem logger, e.g. by the `SubsystemSetField()` function, and across // multiple maps. func SubsystemWarn(ctx context.Context, subsystem, msg string, additionalFields ...map[string]interface{}) { + if !subsystemWouldLog(subsystem, hclog.Warn) { + return + } + logger := logging.GetSDKSubsystemLogger(ctx, subsystem) if logger == nil { if logging.GetSDKRootLogger(ctx) == nil { @@ -197,6 +220,10 @@ func SubsystemWarn(ctx context.Context, subsystem, msg string, additionalFields // subsystem logger, e.g. by the `SubsystemSetField()` function, and across // multiple maps. func SubsystemError(ctx context.Context, subsystem, msg string, additionalFields ...map[string]interface{}) { + if !subsystemWouldLog(subsystem, hclog.Error) { + return + } + logger := logging.GetSDKSubsystemLogger(ctx, subsystem) if logger == nil { if logging.GetSDKRootLogger(ctx) == nil { diff --git a/tfsdklog/subsystem_test.go b/tfsdklog/subsystem_test.go index 7c7c77d..324cf64 100644 --- a/tfsdklog/subsystem_test.go +++ b/tfsdklog/subsystem_test.go @@ -7,6 +7,7 @@ import ( "testing" "github.com/google/go-cmp/cmp" + "github.com/hashicorp/go-hclog" "github.com/hashicorp/terraform-plugin-log/internal/loggertest" "github.com/hashicorp/terraform-plugin-log/tfsdklog" ) @@ -16,6 +17,26 @@ const ( testSubsystemModule = "sdk." + testSubsystem ) +func BenchmarkSubsystemTraceDisabled(b *testing.B) { + benchmarkSubsystemTrace(b, hclog.Debug) +} + +func BenchmarkSubsystemTraceEnabled(b *testing.B) { + benchmarkSubsystemTrace(b, hclog.Trace) +} + +func benchmarkSubsystemTrace(b *testing.B, setLevel hclog.Level) { + var outputBuffer bytes.Buffer + + ctx := context.Background() + ctx = loggertest.SDKRoot(ctx, &outputBuffer) + ctx = tfsdklog.NewSubsystem(ctx, b.Name(), tfsdklog.WithLevel(setLevel)) + + for n := 0; n < b.N; n++ { + tfsdklog.SubsystemTrace(ctx, b.Name(), "test message") + } +} + func TestSubsystemSetField(t *testing.T) { t.Parallel()