From 5ed62c2cee80ef836bb830396226d7219723270b 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/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 | 29 ++++++++++++++++ trace/logr.go | 73 ++++++++++++++++++++++++++++++++++++++++ trace/stash.go | 60 +++++++++++++++++++++++++++++++++ 14 files changed, 269 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/aggregate.go b/reconcilers/aggregate.go index dbcc148..527beb5 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" ) @@ -104,6 +105,11 @@ type AggregateReconciler[Type client.Object] struct { // +optional Sanitize func(resource Type) interface{} + // Trace the execution of each request using this tracer. + // + // +optional + Trace trace.Tracer + Config Config // stamp manages the lifecycle of the aggregated resource. @@ -215,8 +221,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). @@ -224,6 +228,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.StashTracer(ctx, r.Trace) + 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 9aa93a5..6203dfb 100644 --- a/reconcilers/finalizer.go +++ b/reconcilers/finalizer.go @@ -23,6 +23,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" @@ -92,6 +93,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 956fd2e..423eb6a 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 ( @@ -83,6 +84,11 @@ type ResourceReconciler[Type client.Object] struct { // returned. Reconciler SubReconciler[Type] + // Trace the execution of each request using this tracer. + // + // +optional + Trace trace.Tracer + Config Config lazyInit sync.Once @@ -193,8 +199,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). @@ -202,6 +206,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.StashTracer(ctx, r.Trace) + 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 843e5ed..6640535 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 @@ -74,6 +76,11 @@ type AdmissionWebhookAdapter[Type client.Object] struct { // Typically, Reconciler is a Sequence of multiple SubReconcilers. Reconciler SubReconciler[Type] + // Trace the execution of each request using this tracer. + // + // +optional + Trace trace.Tracer + Config Config lazyInit sync.Once @@ -130,6 +137,10 @@ func (r *AdmissionWebhookAdapter[T]) Handle(ctx context.Context, req admission.R ) ctx = logr.NewContext(ctx, log) + ctx = trace.StashTracer(ctx, r.Trace) + 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..96407e2 --- /dev/null +++ b/trace/interface.go @@ -0,0 +1,29 @@ +/* +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) +} diff --git a/trace/logr.go b/trace/logr.go new file mode 100644 index 0000000..0b62b95 --- /dev/null +++ b/trace/logr.go @@ -0,0 +1,73 @@ +/* +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{}, + } +} + +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..ff8c41c --- /dev/null +++ b/trace/stash.go @@ -0,0 +1,60 @@ +/* +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 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{} +}