Add a metric to measure how long resolving policy templates take

Signed-off-by: Chunxi Luo <chuluo@redhat.com>

controllers/configurationpolicy_controller.go

@@ -127,6 +127,8 @@ func (r *ConfigurationPolicyReconciler) Reconcile(ctx context.Context, request c
 		// If the metric was not deleted, that means the policy was never evaluated so it can be ignored.
 		_ = policyEvalSecondsCounter.DeleteLabelValues(request.Name)
 		_ = policyEvalCounter.DeleteLabelValues(request.Name)
+		_ = plcTempsProcessSecondsCounter.DeleteLabelValues(request.Name)
+		_ = plcTempsProcessCounter.DeleteLabelValues(request.Name)
 		_ = compareObjEvalCounter.DeletePartialMatch(prometheus.Labels{"config_policy_name": request.Name})
 		_ = compareObjSecondsCounter.DeletePartialMatch(prometheus.Labels{"config_policy_name": request.Name})
 		_ = policyRelatedObjectGauge.DeletePartialMatch(
@@ -734,6 +736,8 @@ func (r *ConfigurationPolicyReconciler) handleObjectTemplates(plc policyv1.Confi
 	log.V(2).Info("Processing the object templates", "count", len(plc.Spec.ObjectTemplates))
 
 	if !disableTemplates {
+		startTime := time.Now().UTC()
+
 		for _, objectT := range plc.Spec.ObjectTemplates {
 			// first check to make sure there are no hub-templates with delimiter - {{hub
 			// if one exists, it means the template resolution on the hub did not succeed.
@@ -827,6 +831,12 @@ func (r *ConfigurationPolicyReconciler) handleObjectTemplates(plc policyv1.Confi
 				objectT.ObjectDefinition.Raw = resolvedTemplate.ResolvedJSON
 			}
 		}
+
+		if r.EnableMetrics {
+			durationSeconds := time.Since(startTime).Seconds()
+			plcTempsProcessSecondsCounter.WithLabelValues(plc.GetName()).Add(durationSeconds)
+			plcTempsProcessCounter.WithLabelValues(plc.GetName()).Inc()
+		}
 	}
 
 	// Parse and fetch details from each object in each objectTemplate, and gather namespaces if required

controllers/metric.go

@@ -35,6 +35,22 @@ var (
 		},
 		[]string{"name"},
 	)
+	plcTempsProcessSecondsCounter = prometheus.NewCounterVec(
+		prometheus.CounterOpts{
+			Name: "config_policy_templates_process_seconds_total",
+			Help: "The total seconds taken while processing the configuration policy templates. Use this alongside " +
+				"config_policy_templates_process_total.",
+		},
+		[]string{"name"},
+	)
+	plcTempsProcessCounter = prometheus.NewCounterVec(
+		prometheus.CounterOpts{
+			Name: "config_policy_templates_process_total",
+			Help: "The total number of processes of the configuration policy templates. Use this alongside " +
+				"config_policy_templates_process_seconds_total.",
+		},
+		[]string{"name"},
+	)
 	compareObjSecondsCounter = prometheus.NewCounterVec(
 		prometheus.CounterOpts{
 			Name: "compare_objects_seconds_total",
@@ -94,6 +110,8 @@ func init() {
 	metrics.Registry.MustRegister(evalLoopHistogram)
 	metrics.Registry.MustRegister(policyEvalSecondsCounter)
 	metrics.Registry.MustRegister(policyEvalCounter)
+	metrics.Registry.MustRegister(plcTempsProcessSecondsCounter)
+	metrics.Registry.MustRegister(plcTempsProcessCounter)
 	metrics.Registry.MustRegister(compareObjSecondsCounter)
 	metrics.Registry.MustRegister(compareObjEvalCounter)
 	metrics.Registry.MustRegister(policyRelatedObjectGauge)

test/e2e/case13_templatization_test.go

@@ -5,6 +5,8 @@ package e2e
 
 import (
 	"context"
+	"fmt"
+	"strconv"
 	"time"
 
 	. "github.com/onsi/ginkgo/v2"
@@ -258,6 +260,41 @@ var _ = Describe("Test templatization", func() {
 			By("Sleeping 30 seconds to ensure PeriodicallyExecConfigPolicies has rerun twice")
 			time.Sleep(30 * time.Second)
 
+			By("Checking metric endpoint for policy template counter for policy " + case13UpdateRefObject)
+			Eventually(func() interface{} {
+				return utils.GetMetrics(
+					"config_policy_templates_process_total",
+					fmt.Sprintf(`name=\"%s\"`, case13UpdateRefObject),
+				)
+			}, defaultTimeoutSeconds, 1).Should(Not(BeNil()))
+			templatesTotalCounter := utils.GetMetrics(
+				"config_policy_templates_process_total",
+				fmt.Sprintf(`name=\"%s\"`, case13UpdateRefObject),
+			)
+			totalCounter, err := strconv.Atoi(templatesTotalCounter[0])
+			Expect(err).To(BeNil())
+			if err == nil {
+				Expect(totalCounter > 0).To(BeTrue())
+			}
+			By("Policy " + case13UpdateRefObject + " total template process counter : " + templatesTotalCounter[0])
+
+			Eventually(func() interface{} {
+				return utils.GetMetrics(
+					"config_policy_templates_process_seconds_total",
+					fmt.Sprintf(`name=\"%s\"`, case13UpdateRefObject),
+				)
+			}, defaultTimeoutSeconds, 1).Should(Not(BeNil()))
+			templatesTotalSeconds := utils.GetMetrics(
+				"config_policy_templates_process_seconds_total",
+				fmt.Sprintf(`name=\"%s\"`, case13UpdateRefObject),
+			)
+			templatesSeconds, err := strconv.ParseFloat(templatesTotalSeconds[0], 32)
+			Expect(err).To(BeNil())
+			if err == nil {
+				Expect(templatesSeconds > 0).To(BeTrue())
+			}
+			By("Policy " + case13UpdateRefObject + " total template process seconds : " + templatesTotalSeconds[0])
+
 			By("Updating the referenced ConfigMap")
 			configMap.Data["message"] = "Hello world!"
 			_, err = clientManaged.CoreV1().ConfigMaps("default").Update(