From 803aa68bba5537b8787f5970df48ff5c47474208 Mon Sep 17 00:00:00 2001
From: Joel Speed <Joel.speed@hotmail.co.uk>
Date: Mon, 3 Sep 2018 14:59:05 +0100
Subject: [PATCH] Add reconcile time histogram

---
 pkg/internal/controller/controller.go      |  6 +++--
 pkg/internal/controller/controller_test.go | 31 ++++++++++++++++++++++
 pkg/internal/controller/metrics/metrics.go |  6 +++++
 3 files changed, 41 insertions(+), 2 deletions(-)

diff --git a/pkg/internal/controller/controller.go b/pkg/internal/controller/controller.go
index 5e209cee82..9ded3167ed 100644
--- a/pkg/internal/controller/controller.go
+++ b/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())
 }
diff --git a/pkg/internal/controller/controller_test.go b/pkg/internal/controller/controller_test.go
index 2aa214a67f..ea557a978d 100644
--- a/pkg/internal/controller/controller_test.go
+++ b/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)
+			})
 		})
 	})
 })
diff --git a/pkg/internal/controller/metrics/metrics.go b/pkg/internal/controller/metrics/metrics.go
index cc43e5a5ae..14ccb2fc41 100644
--- a/pkg/internal/controller/metrics/metrics.go
+++ b/pkg/internal/controller/metrics/metrics.go
@@ -31,9 +31,15 @@ var (
 		Name: "controller_runtime_reconcile_errors_total",
 		Help: "Total number of reconcile errors per controller",
 	}, []string{"controller"})
+
+	ReconcileTime = prometheus.NewHistogramVec(prometheus.HistogramOpts{
+		Name: "controller_runtime_reconcile_time_second",
+		Help: "Length of time per reconcile per controller",
+	}, []string{"controller"})
 )
 
 func init() {
 	metrics.Registry.MustRegister(QueueLength)
 	metrics.Registry.MustRegister(ReconcileErrors)
+	metrics.Registry.MustRegister(ReconcileTime)
 }