Add a metric to measure how long resolving policy templates take

Signed-off-by: Chunxi Luo <chuluo@redhat.com>
(cherry picked from commit 8695a8d)

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(