Add a new config and metric for reporting ruler query execution wall …

…time. (cortexproject#4317)

* Add a new config and metric for reporting ruler query execution wall time.

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* Spacing and PR number fixup

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* Wrap the defer in a function to make it defer after the return rather than after the if block. Add a unit test to validate we're tracking time correctly.

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* Use seconds for our duration rather than nanoseconds

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* Review comment fixes

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* Update config flag in the config docs

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* Pass counter rather than counter vector for metrics query function

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* Fix comment in MetricsQueryFunction

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* Move query metric and log to separate function. Add log message for ruler query time.

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* Update config file and change log to show this a per user metric

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* code review fixes

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* update log message for ruler query metrics

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* Remove append and just use the array for key values in the log messag

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>

* Add query-frontend component to front end log message

Signed-off-by: Tyler Reid <tyler.reid@grafana.com>
Signed-off-by: Alvin Lin <alvinlin@amazon.com>

CHANGELOG.md

@@ -1,6 +1,7 @@
 # Changelog
 
 ## master / unreleased
+* [FEATURE] Ruler: Add new `-ruler.query-stats-enabled` which when enabled will report the `cortex_ruler_query_seconds_total` as a per-user metric that tracks the sum of the wall time of executing queries in the ruler in seconds. #4317
 
 * [CHANGE] Querier / ruler: Change `-querier.max-fetched-chunks-per-query` configuration to limit to maximum number of chunks that can be fetched in a single query. The number of chunks fetched by ingesters AND long-term storare combined should not exceed the value configured on `-querier.max-fetched-chunks-per-query`. #4260
 * [ENHANCEMENT] Add timeout for waiting on compactor to become ACTIVE in the ring. #4262

docs/configuration/config-file-reference.md

@@ -1617,6 +1617,11 @@ ring:
 # processing will ignore them instead. Subject to sharding.
 # CLI flag: -ruler.disabled-tenants
 [disabled_tenants: <string> | default = ""]
+
+# Report the wall time for ruler queries to complete as a per user metric and as
+# an info level log message.
+# CLI flag: -ruler.query-stats-enabled
+[query_stats_enabled: <boolean> | default = false]
 ```
 
 ### `ruler_storage_config`

pkg/frontend/transport/handler.go

@@ -173,6 +173,7 @@ func (f *Handler) reportQueryStats(r *http.Request, queryString url.Values, quer
 	// Log stats.
 	logMessage := append([]interface{}{
 		"msg", "query stats",
+		"component", "query-frontend",
 		"method", r.Method,
 		"path", r.URL.Path,
 		"response_time", queryResponseTime,

pkg/ruler/compat.go

@@ -6,6 +6,7 @@ import (
 	"time"
 
 	"github.com/go-kit/kit/log"
+	"github.com/go-kit/kit/log/level"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
 	"github.com/prometheus/prometheus/notifier"
@@ -20,6 +21,7 @@ import (
 
 	"github.com/cortexproject/cortex/pkg/cortexpb"
 	"github.com/cortexproject/cortex/pkg/querier"
+	util_log "github.com/cortexproject/cortex/pkg/util/log"
 )
 
 // Pusher is an ingester server that accepts pushes.
@@ -146,9 +148,7 @@ func EngineQueryFunc(engine *promql.Engine, q storage.Queryable, overrides Rules
 func MetricsQueryFunc(qf rules.QueryFunc, queries, failedQueries prometheus.Counter) rules.QueryFunc {
 	return func(ctx context.Context, qs string, t time.Time) (promql.Vector, error) {
 		queries.Inc()
-
 		result, err := qf(ctx, qs, t)
-
 		// We rely on TranslateToPromqlApiError to do its job here... it returns nil, if err is nil.
 		// It returns promql.ErrStorage, if error should be reported back as 500.
 		// Other errors it returns are either for canceled or timed-out queriers (we're not reporting those as failures),
@@ -163,6 +163,33 @@ func MetricsQueryFunc(qf rules.QueryFunc, queries, failedQueries prometheus.Coun
 	}
 }
 
+func RecordAndReportRuleQueryMetrics(qf rules.QueryFunc, queryTime prometheus.Counter, logger log.Logger) rules.QueryFunc {
+	if queryTime == nil {
+		return qf
+	}
+
+	return func(ctx context.Context, qs string, t time.Time) (promql.Vector, error) {
+		// If we've been passed a counter we want to record the wall time spent executing this request.
+		timer := prometheus.NewTimer(nil)
+		defer func() {
+			querySeconds := timer.ObserveDuration().Seconds()
+			queryTime.Add(querySeconds)
+
+			// Log ruler query stats.
+			logMessage := []interface{}{
+				"msg", "query stats",
+				"component", "ruler",
+				"cortex_ruler_query_seconds_total", querySeconds,
+				"query", qs,
+			}
+			level.Info(util_log.WithContext(ctx, logger)).Log(logMessage...)
+		}()
+
+		result, err := qf(ctx, qs, t)
+		return result, err
+	}
+}
+
 // This interface mimicks rules.Manager API. Interface is used to simplify tests.
 type RulesManager interface {
 	// Starts rules manager. Blocks until Stop is called.
@@ -199,12 +226,24 @@ func DefaultTenantManagerFactory(cfg Config, p Pusher, q storage.Queryable, engi
 		Name: "cortex_ruler_queries_failed_total",
 		Help: "Number of failed queries by ruler.",
 	})
+	var rulerQuerySeconds *prometheus.CounterVec
+	if cfg.EnableQueryStats {
+		rulerQuerySeconds = promauto.With(reg).NewCounterVec(prometheus.CounterOpts{
+			Name: "cortex_ruler_query_seconds_total",
+			Help: "Total amount of wall clock time spent processing queries by the ruler.",
+		}, []string{"user"})
+	}
 
 	return func(ctx context.Context, userID string, notifier *notifier.Manager, logger log.Logger, reg prometheus.Registerer) RulesManager {
+		var queryTime prometheus.Counter = nil
+		if rulerQuerySeconds != nil {
+			queryTime = rulerQuerySeconds.WithLabelValues(userID)
+		}
+
 		return rules.NewManager(&rules.ManagerOptions{
 			Appendable:      NewPusherAppendable(p, userID, overrides, totalWrites, failedWrites),
 			Queryable:       q,
-			QueryFunc:       MetricsQueryFunc(EngineQueryFunc(engine, q, overrides, userID), totalQueries, failedQueries),
+			QueryFunc:       RecordAndReportRuleQueryMetrics(MetricsQueryFunc(EngineQueryFunc(engine, q, overrides, userID), totalQueries, failedQueries), queryTime, logger),
 			Context:         user.InjectOrgID(ctx, userID),
 			ExternalURL:     cfg.ExternalURL.URL,
 			NotifyFunc:      SendAlerts(notifier, cfg.ExternalURL.URL.String()),

pkg/ruler/compat_test.go

@@ -8,6 +8,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/go-kit/kit/log"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/testutil"
 	"github.com/prometheus/common/model"
@@ -230,7 +231,6 @@ func TestMetricsQueryFuncErrors(t *testing.T) {
 			mockFunc := func(ctx context.Context, q string, t time.Time) (promql.Vector, error) {
 				return promql.Vector{}, tc.returnedError
 			}
-
 			qf := MetricsQueryFunc(mockFunc, queries, failures)
 
 			_, err := qf(context.Background(), "test", time.Now())
@@ -241,3 +241,16 @@ func TestMetricsQueryFuncErrors(t *testing.T) {
 		})
 	}
 }
+
+func TestRecordAndReportRuleQueryMetrics(t *testing.T) {
+	queryTime := prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"user"})
+
+	mockFunc := func(ctx context.Context, q string, t time.Time) (promql.Vector, error) {
+		time.Sleep(1 * time.Second)
+		return promql.Vector{}, nil
+	}
+	qf := RecordAndReportRuleQueryMetrics(mockFunc, queryTime.WithLabelValues("userID"), log.NewNopLogger())
+	_, _ = qf(context.Background(), "test", time.Now())
+
+	require.GreaterOrEqual(t, testutil.ToFloat64(queryTime.WithLabelValues("userID")), float64(1))
+}

pkg/ruler/ruler.go

@@ -115,6 +115,8 @@ type Config struct {
 	DisabledTenants flagext.StringSliceCSV `yaml:"disabled_tenants"`
 
 	RingCheckPeriod time.Duration `yaml:"-"`
+
+	EnableQueryStats bool `yaml:"query_stats_enabled"`
 }
 
 // Validate config and returns error on failure
@@ -173,6 +175,8 @@ func (cfg *Config) RegisterFlags(f *flag.FlagSet) {
 	f.Var(&cfg.EnabledTenants, "ruler.enabled-tenants", "Comma separated list of tenants whose rules this ruler can evaluate. If specified, only these tenants will be handled by ruler, otherwise this ruler can process rules from all tenants. Subject to sharding.")
 	f.Var(&cfg.DisabledTenants, "ruler.disabled-tenants", "Comma separated list of tenants whose rules this ruler cannot evaluate. If specified, a ruler that would normally pick the specified tenant(s) for processing will ignore them instead. Subject to sharding.")
 
+	f.BoolVar(&cfg.EnableQueryStats, "ruler.query-stats-enabled", false, "Report the wall time for ruler queries to complete as a per user metric and as an info level log message.")
+
 	cfg.RingCheckPeriod = 5 * time.Second
 }
 

pkg/ruler/ruler_test.go

@@ -60,6 +60,7 @@ func defaultRulerConfig(store rulestore.RuleStore) (Config, func()) {
 	cfg.Ring.ListenPort = 0
 	cfg.Ring.InstanceAddr = "localhost"
 	cfg.Ring.InstanceID = "localhost"
+	cfg.EnableQueryStats = false
 
 	// Create a cleanup function that will be called at the end of the test
 	cleanup := func() {