From baab61cc2e65f17912fce39437b216ca27d8f1a4 Mon Sep 17 00:00:00 2001 From: Brian Flad Date: Wed, 31 May 2023 17:19:20 -0400 Subject: [PATCH] tfsdklog: Introduce outside context level checks for logging functions (#149) Reference: https://github.com/hashicorp/terraform-plugin-framework/issues/721 This change introduces log level checks outside the `context.Context` of a request to improve the performance of logging functions when logs would not be emitted at the configured level. Almost exclusively, logging levels are not expected to change during provider (and therefore SDK) runtime since they are environment variable driven. Even if they did, this level check will either immediately constrict logging to match an updated higher level or cause additional `context.Context` reads with an updated lower level, which is no different than the current behavior. The following benchmark was ran prior to the introduction of the level checks and mutexes: ``` BenchmarkSubsystemTraceDisabled-10 4616656 258.0 ns/op BenchmarkSubsystemTraceEnabled-10 936865 1138 ns/op ``` After the addition of level checks and mutexes: ``` BenchmarkSubsystemTraceDisabled-10 86043471 13.78 ns/op BenchmarkSubsystemTraceEnabled-10 906649 1137 ns/op ``` This enhancement could also be considered for provider loggers, however SDK logging tends to be more prevalent in practice, so this only targets the `tfsdklog` package handling. --- .../ENHANCEMENTS-20230418-201952.yaml | 6 + tfsdklog/levels.go | 81 +++++ tfsdklog/levels_test.go | 331 ++++++++++++++++++ tfsdklog/sdk.go | 8 + tfsdklog/subsystem.go | 27 ++ tfsdklog/subsystem_test.go | 21 ++ 6 files changed, 474 insertions(+) create mode 100644 .changes/unreleased/ENHANCEMENTS-20230418-201952.yaml create mode 100644 tfsdklog/levels.go create mode 100644 tfsdklog/levels_test.go 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()