k8s.io/kubernetes@v1.29.3/test/integration/logs/benchmark/contextual-logging/benchmark_test.go (about) 1 /* 2 Copyright 2021 The Kubernetes Authors. 3 4 Licensed under the Apache License, Version 2.0 (the "License"); 5 you may not use this file except in compliance with the License. 6 You may obtain a copy of the License at 7 8 http://www.apache.org/licenses/LICENSE-2.0 9 10 Unless required by applicable law or agreed to in writing, software 11 distributed under the License is distributed on an "AS IS" BASIS, 12 WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 See the License for the specific language governing permissions and 14 limitations under the License. 15 */ 16 17 package contextuallogging 18 19 import ( 20 "context" 21 "fmt" 22 "testing" 23 "time" 24 25 "github.com/go-logr/logr" 26 27 "k8s.io/klog/v2" 28 ) 29 30 func init() { 31 klog.InitFlags(nil) 32 } 33 34 // BenchmarkRecursion measures the overhead of adding calling a function 35 // recursively with just the depth parameter. 36 func BenchmarkRecursion(b *testing.B) { 37 for depth := 10; depth <= 100000; depth *= 10 { 38 b.Run(fmt.Sprintf("%d", depth), func(b *testing.B) { 39 for i := 0; i < b.N; i++ { 40 recurse(depth) 41 } 42 }) 43 } 44 } 45 46 //go:noinline 47 func recurse(depth int) { 48 if depth == 0 { 49 logr.Discard().Info("hello world") 50 return 51 } 52 recurse(depth - 1) 53 } 54 55 // BenchmarkRecursionWithLogger measures the overhead of adding a logr.Logger 56 // parameter. 57 func BenchmarkRecursionWithLogger(b *testing.B) { 58 logger := logr.Discard() 59 60 for depth := 10; depth <= 100000; depth *= 10 { 61 b.Run(fmt.Sprintf("%d", depth), func(b *testing.B) { 62 for i := 0; i < b.N; i++ { 63 recurseWithLogger(logger, depth) 64 } 65 }) 66 } 67 } 68 69 //go:noinline 70 func recurseWithLogger(logger logr.Logger, depth int) { 71 if depth == 0 { 72 return 73 } 74 recurseWithLogger(logger, depth-1) 75 } 76 77 // BenchmarkRecursionWithContext measures the overhead of adding a context 78 // parameter. 79 func BenchmarkRecursionWithContext(b *testing.B) { 80 logger := logr.Discard() 81 // nolint:logcheck // Intentionally using NewContext unconditionally here. 82 ctx := logr.NewContext(context.Background(), logger) 83 84 for depth := 10; depth <= 100000; depth *= 10 { 85 b.Run(fmt.Sprintf("%d", depth), func(b *testing.B) { 86 for i := 0; i < b.N; i++ { 87 recurseWithContext(ctx, depth) 88 } 89 }) 90 } 91 } 92 93 //go:noinline 94 func recurseWithContext(ctx context.Context, depth int) { 95 if depth == 0 { 96 return 97 } 98 recurseWithContext(ctx, depth-1) 99 } 100 101 // BenchmarkRecursionWithLogger measures the overhead of adding a logr.Logger 102 // parameter and using it once. 103 func BenchmarkRecursionWithLoggerAndLog(b *testing.B) { 104 logger := logr.Discard() 105 106 for depth := 10; depth <= 100000; depth *= 10 { 107 b.Run(fmt.Sprintf("%d", depth), func(b *testing.B) { 108 for i := 0; i < b.N; i++ { 109 recurseWithLoggerAndLog(logger, depth) 110 } 111 }) 112 } 113 } 114 115 //go:noinline 116 func recurseWithLoggerAndLog(logger logr.Logger, depth int) { 117 if depth == 0 { 118 logger.Info("hello world") 119 return 120 } 121 recurseWithLoggerAndLog(logger, depth-1) 122 } 123 124 // BenchmarkRecursionWithContext measures the overhead of adding a context 125 // parameter and using it once to retrieve and call a logger. 126 func BenchmarkRecursionWithContextAndLog(b *testing.B) { 127 logger := logr.Discard() 128 // nolint:logcheck // Intentionally using NewContext unconditionally here. 129 ctx := logr.NewContext(context.Background(), logger) 130 131 for depth := 10; depth <= 100000; depth *= 10 { 132 b.Run(fmt.Sprintf("%d", depth), func(b *testing.B) { 133 for i := 0; i < b.N; i++ { 134 recurseWithContextAndLog(ctx, depth) 135 } 136 }) 137 } 138 } 139 140 //go:noinline 141 func recurseWithContextAndLog(ctx context.Context, depth int) { 142 if depth == 0 { 143 logger := logr.FromContextOrDiscard(ctx) 144 logger.Info("hello world") 145 return 146 } 147 recurseWithContextAndLog(ctx, depth-1) 148 } 149 150 // BenchmarkNestedContextWithTimeouts benchmarks how quickly a function can be 151 // called that creates a new context at each call with context.WithTimeout. 152 func BenchmarkNestedContextWithTimeouts(b *testing.B) { 153 ctx := context.Background() 154 155 for depth := 1; depth <= 10000; depth *= 10 { 156 b.Run(fmt.Sprintf("%d", depth), func(b *testing.B) { 157 for i := 0; i < b.N; i++ { 158 nestedContextWithTimeout(ctx, depth) 159 } 160 }) 161 } 162 } 163 164 //go:noinline 165 func nestedContextWithTimeout(ctx context.Context, depth int) { 166 if depth == 0 { 167 return 168 } 169 ctx, cancel := context.WithTimeout(ctx, time.Hour) 170 defer cancel() 171 nestedContextWithTimeout(ctx, depth-1) 172 } 173 174 // BenchmarkNestedContextWithTimeouts benchmarks how quickly a function can be 175 // called that creates a new context at each call with context.WithTimeout 176 // and then looks up a logger. 177 func BenchmarkNestedContextWithTimeoutsAndLookup(b *testing.B) { 178 // nolint:logcheck // Intentionally using NewContext unconditionally here. 179 ctx := logr.NewContext(context.Background(), logr.Discard()) 180 181 for depth := 1; depth <= 10000; depth *= 10 { 182 b.Run(fmt.Sprintf("%d", depth), func(b *testing.B) { 183 for i := 0; i < b.N; i++ { 184 nestedContextWithTimeoutAndLookup(ctx, depth) 185 } 186 }) 187 } 188 } 189 190 //go:noinline 191 func nestedContextWithTimeoutAndLookup(ctx context.Context, depth int) { 192 if depth == 0 { 193 logr.FromContextOrDiscard(ctx) 194 return 195 } 196 ctx, cancel := context.WithTimeout(ctx, time.Hour) 197 defer cancel() 198 nestedContextWithTimeoutAndLookup(ctx, depth-1) 199 } 200 201 var logger logr.Logger 202 203 // BenchmarkNestedContextWithTimeouts benchmarks how quickly FromContextOrDiscard 204 // can look up a logger in nested contexts where WithTimeouts is used to 205 // created those nested contexts. 206 func BenchmarkLookupWithTimeouts(b *testing.B) { 207 for depth := 1; depth <= 10000; depth *= 10 { 208 b.Run(fmt.Sprintf("%d", depth), func(b *testing.B) { 209 // nolint:logcheck // Intentionally using NewContext unconditionally here. 210 ctx := logr.NewContext(context.Background(), logr.Discard()) 211 for i := 0; i < depth; i++ { 212 ctx2, cancel := context.WithTimeout(ctx, time.Hour) 213 defer cancel() 214 ctx = ctx2 215 } 216 b.ResetTimer() 217 for i := 0; i < b.N; i++ { 218 logger = logr.FromContextOrDiscard(ctx) 219 } 220 }) 221 } 222 } 223 224 type keyT struct{} 225 226 var key keyT 227 228 // BenchmarkNestedContextWithTimeouts benchmarks how quickly FromContextOrDiscard 229 // can look up a logger in nested contexts where WithValue is used to 230 // created those nested contexts. 231 func BenchmarkLookupWithValues(b *testing.B) { 232 for depth := 1; depth <= 10000; depth *= 10 { 233 b.Run(fmt.Sprintf("%d", depth), func(b *testing.B) { 234 // nolint:logcheck // Intentionally using NewContext unconditionally here. 235 ctx := logr.NewContext(context.Background(), logr.Discard()) 236 for i := 0; i < depth; i++ { 237 ctx = context.WithValue(ctx, key, depth) 238 } 239 b.ResetTimer() 240 for i := 0; i < b.N; i++ { 241 logger = logr.FromContextOrDiscard(ctx) 242 } 243 }) 244 } 245 }