benchmark_test.go

Documentation: k8s.io/kubernetes/test/integration/logs/benchmark/contextual-logging

     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  }
   246
View as plain text