Add reconcile time histogram

Author: JoelSpeed

pkg/internal/controller/controller.go

@@ -173,7 +173,8 @@ func (c *Controller) processNextWorkItem() bool {
 	// This code copy-pasted from the sample-Controller.
 
 	// Update metrics after processing each item
-	defer c.updateMetrics()
+	reconcileStartTS := time.Now()
+	defer c.updateMetrics(time.Now().Sub(reconcileStartTS))
 
 	obj, shutdown := c.Queue.Get()
 	if obj == nil {
@@ -240,6 +241,7 @@ func (c *Controller) InjectFunc(f inject.Func) error {
 }
 
 // updateMetrics updates prometheus metrics within the controller
-func (c *Controller) updateMetrics() {
+func (c *Controller) updateMetrics(reconcileTime time.Duration) {
 	ctrlmetrics.QueueLength.WithLabelValues(c.Name).Set(float64(c.Queue.Len()))
+	ctrlmetrics.ReconcileTime.WithLabelValues(c.Name).Observe(reconcileTime.Seconds())
 }

pkg/internal/controller/controller_test.go

@@ -457,6 +457,37 @@ var _ = Describe("controller", func() {
 
 				close(done)
 			}, 2.0)
+
+			It("should add a reconcile time to the reconcile time histogram", func(done Done) {
+				ctrlmetrics.ReconcileTime = prometheus.NewHistogramVec(prometheus.HistogramOpts{
+					Name: "controller_runtime_reconcile_time_second",
+					Help: "Length of time per reconcile per controller",
+				}, []string{"controller"})
+
+				go func() {
+					defer GinkgoRecover()
+					Expect(ctrl.Start(stop)).NotTo(HaveOccurred())
+				}()
+				ctrl.Queue.Add(request)
+
+				By("Invoking Reconciler")
+				Expect(<-reconciled).To(Equal(request))
+
+				By("Removing the item from the queue")
+				Eventually(ctrl.Queue.Len).Should(Equal(0))
+				Eventually(func() int { return ctrl.Queue.NumRequeues(request) }).Should(Equal(0))
+
+				var reconcileTime dto.Metric
+				Eventually(func() error {
+					ctrlmetrics.ReconcileTime.WithLabelValues(ctrl.Name).Write(&reconcileTime)
+					if reconcileTime.GetHistogram().GetSampleCount() != uint64(1) {
+						return fmt.Errorf("metrics not updated")
+					}
+					return nil
+				}, 2.0).Should(Succeed())
+
+				close(done)
+			}, 4.0)
 		})
 	})
 })

pkg/internal/controller/metrics/metrics.go

@@ -35,9 +35,17 @@ var (
 		Name: "controller_runtime_reconcile_errors_total",
 		Help: "Total number of reconcile errors per controller",
 	}, []string{"controller"})
+
+	// ReconcileTime is a prometheus metric which keeps track of the duration
+	// of reconciles
+	ReconcileTime = prometheus.NewHistogramVec(prometheus.HistogramOpts{
+		Name: "controller_runtime_reconcile_time_seconds",
+		Help: "Length of time per reconcile per controller",
+	}, []string{"controller"})
 )
 
 func init() {
 	metrics.Registry.MustRegister(QueueLength)
 	metrics.Registry.MustRegister(ReconcileErrors)
+	metrics.Registry.MustRegister(ReconcileTime)
 }