From d1d8f00948166275371ef179305b4eec891729cd Mon Sep 17 00:00:00 2001 From: Scott Andrews Date: Wed, 3 Apr 2024 20:45:49 -0400 Subject: [PATCH] Trace the execution of a reconciler hierarchy Introduces a Tracer interface that can be provided to the Reconciler and Webhook handler implementations when they are defined. Each provided SubReconciler is instrumented to enter a new frame when it's Reconcile method is called and exit upon return. Two implementations are provided out of the box. DiscardTracer ignores all calls. LogrTracer logs as each frame enters and exits, capturing the elapsed time. Custom SubReconcilers and other aspects of the call stack can be instrumented: import "reconciler.io/runtime/trace" ... trace.Enter(ctx, "MEANINGFUL NAME") defer trace.Exit(ctx) Signed-off-by: Scott Andrews --- reconcilers/advice.go | 4 ++ reconcilers/aggregate.go | 13 +++++- reconcilers/cast.go | 14 ++++--- reconcilers/child.go | 4 ++ reconcilers/childset.go | 4 ++ reconcilers/finalizer.go | 4 ++ reconcilers/flow.go | 13 ++++++ reconcilers/resource.go | 13 +++++- reconcilers/sequence.go | 4 ++ reconcilers/sync.go | 4 ++ reconcilers/webhook.go | 15 ++++++- trace/discard.go | 30 ++++++++++++++ trace/interface.go | 31 +++++++++++++++ trace/logr.go | 86 ++++++++++++++++++++++++++++++++++++++++ trace/stash.go | 68 +++++++++++++++++++++++++++++++ 15 files changed, 296 insertions(+), 11 deletions(-) create mode 100644 trace/discard.go create mode 100644 trace/interface.go create mode 100644 trace/logr.go create mode 100644 trace/stash.go diff --git a/reconcilers/advice.go b/reconcilers/advice.go index 7f3bda3..279ff3b 100644 --- a/reconcilers/advice.go +++ b/reconcilers/advice.go @@ -22,6 +22,7 @@ import ( "sync" "github.com/go-logr/logr" + "reconciler.io/runtime/trace" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/builder" "sigs.k8s.io/controller-runtime/pkg/client" @@ -137,6 +138,9 @@ func (r *Advice[T]) Reconcile(ctx context.Context, resource T) (Result, error) { WithName(r.Name) ctx = logr.NewContext(ctx, log) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + // before phase beforeCtx, result, err := r.Before(ctx, resource) if err != nil { diff --git a/reconcilers/aggregate.go b/reconcilers/aggregate.go index cb9d5ec..cd9aab5 100644 --- a/reconcilers/aggregate.go +++ b/reconcilers/aggregate.go @@ -35,6 +35,7 @@ import ( "reconciler.io/runtime/duck" "reconciler.io/runtime/internal" rtime "reconciler.io/runtime/time" + "reconciler.io/runtime/trace" "reconciler.io/runtime/tracker" ) @@ -120,6 +121,11 @@ type AggregateReconciler[Type client.Object] struct { // +optional AfterReconcile func(ctx context.Context, req Request, res Result, err error) (Result, error) + // TraceProvider provides a new tracer for the current reconcile request. + // + // +optional + TraceProvider trace.TraceProvider + Config Config // stamp manages the lifecycle of the aggregated resource. @@ -241,8 +247,6 @@ func (r *AggregateReconciler[T]) Reconcile(ctx context.Context, req Request) (Re return Result{}, nil } - ctx = WithStash(ctx) - c := r.Config log := logr.FromContextOrDiscard(ctx). @@ -250,6 +254,11 @@ func (r *AggregateReconciler[T]) Reconcile(ctx context.Context, req Request) (Re WithValues("resourceType", gvk(c, r.Type)) ctx = logr.NewContext(ctx, log) + ctx = trace.StashTracerFromProvider(ctx, r.TraceProvider) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + + ctx = WithStash(ctx) ctx = rtime.StashNow(ctx, time.Now()) ctx = StashRequest(ctx, req) ctx = StashConfig(ctx, c) diff --git a/reconcilers/cast.go b/reconcilers/cast.go index 97dfbeb..59986bb 100644 --- a/reconcilers/cast.go +++ b/reconcilers/cast.go @@ -24,6 +24,7 @@ import ( "sync" "k8s.io/apimachinery/pkg/util/errors" + "reconciler.io/runtime/trace" "github.com/go-logr/logr" "k8s.io/apimachinery/pkg/api/equality" @@ -105,11 +106,6 @@ func (r *CastResource[T, CT]) validate(ctx context.Context) error { func (r *CastResource[T, CT]) Reconcile(ctx context.Context, resource T) (Result, error) { r.init() - if r.noop { - // cast the type rather than convert the object - return r.Reconciler.Reconcile(ctx, client.Object(resource).(CT)) - } - var nilCT CT emptyCT := newEmpty(nilCT).(CT) @@ -118,6 +114,14 @@ func (r *CastResource[T, CT]) Reconcile(ctx context.Context, resource T) (Result WithValues("castResourceType", typeName(emptyCT)) ctx = logr.NewContext(ctx, log) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + + if r.noop { + // cast the type rather than convert the object + return r.Reconciler.Reconcile(ctx, client.Object(resource).(CT)) + } + ctx, castResource, err := r.cast(ctx, resource) if err != nil { return Result{}, err diff --git a/reconcilers/child.go b/reconcilers/child.go index 18fb293..9373c7e 100644 --- a/reconcilers/child.go +++ b/reconcilers/child.go @@ -32,6 +32,7 @@ import ( "sigs.k8s.io/controller-runtime/pkg/client" "reconciler.io/runtime/internal" + "reconciler.io/runtime/trace" ) var ( @@ -276,6 +277,9 @@ func (r *ChildReconciler[T, CT, CLT]) Reconcile(ctx context.Context, resource T) WithValues("childType", gvk(c, r.ChildType)) ctx = logr.NewContext(ctx, log) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + child, err := r.reconcile(ctx, resource) if resource.GetDeletionTimestamp() != nil { return Result{}, err diff --git a/reconcilers/childset.go b/reconcilers/childset.go index 3d54cc3..aa5ca2f 100644 --- a/reconcilers/childset.go +++ b/reconcilers/childset.go @@ -26,6 +26,7 @@ import ( utilerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/apimachinery/pkg/util/sets" "reconciler.io/runtime/internal" + "reconciler.io/runtime/trace" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/builder" "sigs.k8s.io/controller-runtime/pkg/client" @@ -294,6 +295,9 @@ func (r *ChildSetReconciler[T, CT, CLT]) Reconcile(ctx context.Context, resource WithName(r.Name) ctx = logr.NewContext(ctx, log) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + knownChildren, err := r.knownChildren(ctx, resource) if err != nil { return Result{}, err diff --git a/reconcilers/finalizer.go b/reconcilers/finalizer.go index a32980f..f5890a4 100644 --- a/reconcilers/finalizer.go +++ b/reconcilers/finalizer.go @@ -24,6 +24,7 @@ import ( "github.com/go-logr/logr" corev1 "k8s.io/api/core/v1" + "reconciler.io/runtime/trace" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/builder" "sigs.k8s.io/controller-runtime/pkg/client" @@ -117,6 +118,9 @@ func (r *WithFinalizer[T]) Reconcile(ctx context.Context, resource T) (Result, e WithName(r.Name) ctx = logr.NewContext(ctx, log) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + if resource.GetDeletionTimestamp() == nil { if err := AddFinalizer(ctx, resource, r.Finalizer); err != nil { return Result{}, err diff --git a/reconcilers/flow.go b/reconcilers/flow.go index 53f2ea6..d20bcc0 100644 --- a/reconcilers/flow.go +++ b/reconcilers/flow.go @@ -23,6 +23,7 @@ import ( "github.com/go-logr/logr" "k8s.io/utils/pointer" + "reconciler.io/runtime/trace" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/builder" "sigs.k8s.io/controller-runtime/pkg/client" @@ -125,6 +126,9 @@ func (r *IfThen[T]) Reconcile(ctx context.Context, resource T) (Result, error) { WithName(r.Name) ctx = logr.NewContext(ctx, log) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + if r.If(ctx, resource) { return r.Then.Reconcile(ctx, resource) } else if r.Else != nil { @@ -256,6 +260,9 @@ func (r *While[T]) Reconcile(ctx context.Context, resource T) (Result, error) { WithName(r.Name) ctx = logr.NewContext(ctx, log) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + aggregateResult := Result{} for i := 0; true; i++ { if *r.MaxIterations != 0 && i >= *r.MaxIterations { @@ -387,6 +394,9 @@ func (r *TryCatch[T]) Reconcile(ctx context.Context, resource T) (Result, error) WithName(r.Name) ctx = logr.NewContext(ctx, log) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + result, err := r.Try.Reconcile(ctx, resource) if r.Catch != nil { result, err = r.Catch(ctx, resource, result, err) @@ -474,6 +484,9 @@ func (r *OverrideSetup[T]) Reconcile(ctx context.Context, resource T) (Result, e WithName(r.Name) ctx = logr.NewContext(ctx, log) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + if r.Reconciler == nil { return Result{}, nil } diff --git a/reconcilers/resource.go b/reconcilers/resource.go index 6325bca..25fdb67 100644 --- a/reconcilers/resource.go +++ b/reconcilers/resource.go @@ -41,6 +41,7 @@ import ( "reconciler.io/runtime/duck" "reconciler.io/runtime/internal" rtime "reconciler.io/runtime/time" + "reconciler.io/runtime/trace" ) var ( @@ -99,6 +100,11 @@ type ResourceReconciler[Type client.Object] struct { // +optional AfterReconcile func(ctx context.Context, req Request, res Result, err error) (Result, error) + // TraceProvider provides a new tracer for the current reconcile request. + // + // +optional + TraceProvider trace.TraceProvider + Config Config lazyInit sync.Once @@ -219,8 +225,6 @@ func (r *ResourceReconciler[T]) validate(ctx context.Context) error { func (r *ResourceReconciler[T]) Reconcile(ctx context.Context, req Request) (Result, error) { r.init() - ctx = WithStash(ctx) - c := r.Config log := logr.FromContextOrDiscard(ctx). @@ -228,6 +232,11 @@ func (r *ResourceReconciler[T]) Reconcile(ctx context.Context, req Request) (Res WithValues("resourceType", gvk(c, r.Type)) ctx = logr.NewContext(ctx, log) + ctx = trace.StashTracerFromProvider(ctx, r.TraceProvider) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + + ctx = WithStash(ctx) ctx = rtime.StashNow(ctx, time.Now()) ctx = StashRequest(ctx, req) ctx = StashConfig(ctx, c) diff --git a/reconcilers/sequence.go b/reconcilers/sequence.go index 654c70e..cc1745a 100644 --- a/reconcilers/sequence.go +++ b/reconcilers/sequence.go @@ -21,6 +21,7 @@ import ( "fmt" "github.com/go-logr/logr" + "reconciler.io/runtime/trace" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/builder" "sigs.k8s.io/controller-runtime/pkg/client" @@ -49,6 +50,9 @@ func (r Sequence[T]) SetupWithManager(ctx context.Context, mgr ctrl.Manager, bld } func (r Sequence[T]) Reconcile(ctx context.Context, resource T) (Result, error) { + trace.Enter(ctx, "Sequence") + defer trace.Exit(ctx) + aggregateResult := Result{} for i, reconciler := range r { log := logr.FromContextOrDiscard(ctx). diff --git a/reconcilers/sync.go b/reconcilers/sync.go index 9d549b1..09831e9 100644 --- a/reconcilers/sync.go +++ b/reconcilers/sync.go @@ -22,6 +22,7 @@ import ( "fmt" "github.com/go-logr/logr" + "reconciler.io/runtime/trace" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/builder" "sigs.k8s.io/controller-runtime/pkg/client" @@ -124,6 +125,9 @@ func (r *SyncReconciler[T]) Reconcile(ctx context.Context, resource T) (Result, WithName(r.Name) ctx = logr.NewContext(ctx, log) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + result := Result{} if resource.GetDeletionTimestamp() == nil || r.SyncDuringFinalization { diff --git a/reconcilers/webhook.go b/reconcilers/webhook.go index 900f6fe..830ddc1 100644 --- a/reconcilers/webhook.go +++ b/reconcilers/webhook.go @@ -31,12 +31,14 @@ import ( "k8s.io/apimachinery/pkg/api/equality" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/types" - "reconciler.io/runtime/internal" - rtime "reconciler.io/runtime/time" "sigs.k8s.io/controller-runtime/pkg/client" crlog "sigs.k8s.io/controller-runtime/pkg/log" "sigs.k8s.io/controller-runtime/pkg/webhook" "sigs.k8s.io/controller-runtime/pkg/webhook/admission" + + "reconciler.io/runtime/internal" + rtime "reconciler.io/runtime/time" + "reconciler.io/runtime/trace" ) // AdmissionWebhookAdapter allows using sub reconcilers to process admission webhooks. The full @@ -90,6 +92,11 @@ type AdmissionWebhookAdapter[Type client.Object] struct { // +optional AfterHandle func(ctx context.Context, req admission.Request, resp *admission.Response) + // TraceProvider provides a new tracer for the current webhook request. + // + // +optional + TraceProvider trace.TraceProvider + Config Config lazyInit sync.Once @@ -154,6 +161,10 @@ func (r *AdmissionWebhookAdapter[T]) Handle(ctx context.Context, req admission.R ) ctx = logr.NewContext(ctx, log) + ctx = trace.StashTracerFromProvider(ctx, r.TraceProvider) + trace.Enter(ctx, r.Name) + defer trace.Exit(ctx) + resp := &admission.Response{ AdmissionResponse: admissionv1.AdmissionResponse{ UID: req.UID, diff --git a/trace/discard.go b/trace/discard.go new file mode 100644 index 0000000..50522fb --- /dev/null +++ b/trace/discard.go @@ -0,0 +1,30 @@ +/* +Copyright 2024 the original author or authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package trace + +import ( + "context" +) + +var ( + _ Tracer = (*discardTracer)(nil) +) + +type discardTracer struct{} + +func (d *discardTracer) Enter(ctx context.Context, name string) {} +func (d *discardTracer) Exit(ctx context.Context) {} diff --git a/trace/interface.go b/trace/interface.go new file mode 100644 index 0000000..3b24dcf --- /dev/null +++ b/trace/interface.go @@ -0,0 +1,31 @@ +/* +Copyright 2024 the original author or authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package trace + +import ( + "context" +) + +// Tracer observes the execution of a reconciler hierarchy. +type Tracer interface { + // Enter opens a new frame. + Enter(ctx context.Context, name string) + // Exit closes the most recently entered open frame. + Exit(ctx context.Context) +} + +type TraceProvider = func(ctx context.Context) Tracer diff --git a/trace/logr.go b/trace/logr.go new file mode 100644 index 0000000..151cb71 --- /dev/null +++ b/trace/logr.go @@ -0,0 +1,86 @@ +/* +Copyright 2024 the original author or authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package trace + +import ( + "context" + "fmt" + "time" + + "github.com/go-logr/logr" +) + +var ( + _ Tracer = (*logrTracer)(nil) +) + +// LogrTracer uses the context's logr to capture a message when entering and exiting. The duration +// is captured in nanoseconds as the elapsedNs structured parameter. +// +// Not thread safe. Enter and Exit calls must be balanced. +func LogrTracer(opts LogrTracerOpts) Tracer { + return &logrTracer{ + level: opts.Level, + stack: []time.Time{}, + } +} + +// LogrTraceProvider uses the context's logr to capture a message when entering and exiting. The duration +// is captured in nanoseconds as the elapsedNs structured parameter. +// +// Not thread safe. Enter and Exit calls must be balanced. +func LogrTraceProvider(opts LogrTracerOpts) TraceProvider { + return func(ctx context.Context) Tracer { + return &logrTracer{ + level: opts.Level, + stack: []time.Time{}, + } + } +} + +type LogrTracerOpts struct { + // Level of verbosity to apply to log messages relative to the logger. A higher verbosity level + // means a log message is less important. + Level int +} + +type logrTracer struct { + level int + stack []time.Time +} + +func (t *logrTracer) Enter(ctx context.Context, name string) { + log := logr.FromContextOrDiscard(ctx).V(t.level) + now := time.Now() + t.stack = append(t.stack, now) + log.Info("trace enter") +} + +func (t *logrTracer) Exit(ctx context.Context) { + log := logr.FromContextOrDiscard(ctx).V(t.level) + i := len(t.stack) + if i == 0 { + panic(fmt.Errorf("Exit() called more times than Enter() for a Tracer")) + } + start := t.stack[i-1] + t.stack = t.stack[:i-1] + if !log.Enabled() { + return + } + now := time.Now() + log.Info("trace exit", "elapsedNs", now.Sub(start)) +} diff --git a/trace/stash.go b/trace/stash.go new file mode 100644 index 0000000..54f6291 --- /dev/null +++ b/trace/stash.go @@ -0,0 +1,68 @@ +/* +Copyright 2024 the original author or authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package trace + +import ( + "context" +) + +// Enter the Tracer for the context +func Enter(ctx context.Context, name string) { + RetrieveTracerOrDiscard(ctx).Enter(ctx, name) +} + +// Exit the Tracer for the context +func Exit(ctx context.Context) { + RetrieveTracerOrDiscard(ctx).Exit(ctx) +} + +type tracerKey struct{} + +var tracerStashKey = tracerKey{} + +func StashTracerFromProvider(ctx context.Context, provider TraceProvider) context.Context { + if provider == nil { + return ctx + } + tracer := provider(ctx) + return StashTracer(ctx, tracer) +} + +func StashTracer(ctx context.Context, tracer Tracer) context.Context { + if ctx.Value(tracerStashKey) != nil { + // avoid overwriting + return ctx + } + return context.WithValue(ctx, tracerStashKey, tracer) +} + +// RetrieveTracer returns the stashed tracer. +func RetrieveTracer(ctx context.Context) Tracer { + value := ctx.Value(tracerStashKey) + if tracer, ok := value.(Tracer); ok { + return tracer + } + return nil +} + +// RetrieveTracerOrDiscard returns the stashed tracer. +func RetrieveTracerOrDiscard(ctx context.Context) Tracer { + if tracer := RetrieveTracer(ctx); tracer != nil { + return tracer + } + return &discardTracer{} +}