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{} +}