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 <[email protected]>
reconcilerio · May 28, 2024 · d1d8f00 · d1d8f00
1 parent 597a9ed
commit d1d8f00
Show file tree

Hide file tree

Showing 15 changed files with 296 additions and 11 deletions.
diff --git 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
@@ -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,15 +247,18 @@ func (r *AggregateReconciler[T]) Reconcile(ctx context.Context, req Request) (Re
 		return Result{}, nil
 	}
 
-	ctx = WithStash(ctx)
-
 	c := r.Config
 
 	log := logr.FromContextOrDiscard(ctx).
 		WithName(r.Name).
 		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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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,15 +225,18 @@ 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).
 		WithName(r.Name).
 		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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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