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

[treid314]

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

What this PR does:
This PR adds a new metric for tracking the execution wall time of queries in the ruler. We have a similar metric for query execution time on query front-ends today but we also wish to track query execution time in the rulers. This metric is called cortex_ruler_query_seconds_total and has a label of user containing the UserID of the tenant who is tagged in the rule. This metric can be enabled with the -ruler.query-stats-enabled boolean config option.

Which issue(s) this PR fixes:
Fixes #

Checklist

• Tests updated
• Documentation added
• CHANGELOG.md updated - the order of entries should be [CHANGE], [FEATURE], [ENHANCEMENT], [BUGFIX]

[treid314]

I've seen we use sleep in other unit tests, but it still feels kind of wrong. Is there a better way to simulate time passing?

[bboreham]

Sorry but we have begun the process of cutting a new release; please rebase from master and move your CHANGELOG entry to the top under ## master / unreleased

[pracucci]

Thanks for working on this! I left few comments.

[pracucci]

You can use prometheus.NewTimer() for this purpose, instead of tracking manually.

[cstyan]

@treid314 re: your comment about faking time pasing, we have this package: https://github.com/weaveworks/common/blob/master/mtime/mtime.go

I trust you've all agreed there's a reason to add this metric, but just off the top of my head I'm questioning how useful a metric for the total time spent executing queries in the ruler for a user is. What scenario is this metric here to help diagnose? Would a histogram with only a few buckets not be better? Or logging when the ruler finishes evaluating a rule with a field for how long that took?

[pracucci]

What scenario is this metric here to help diagnose?

It's for billing purposes (reason why it's a counter and not an histogram).

[pracucci]

LGTM (modulo a nit)

[pstibrany]

Nice job. I would suggest to implement this tracking in separate function, to avoid breaking existing clients of MetricsQueryFunc ouside of Cortex.

[pstibrany]

We can simplify this function:

1. we don't need to return new function, if queryTime is nil. No need to check it each time.
2. not sure what's going on with logging here, but we can just call Log, right?

Suggested change

	func RecordAndReportRuleQueryMetrics(qf rules.QueryFunc, queryTime prometheus.Counter, logger log.Logger) rules.QueryFunc {
	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.
	if queryTime != nil {
	timer := prometheus.NewTimer(nil)
	defer func() {
	querySeconds := timer.ObserveDuration().Seconds()
	queryTime.Add(querySeconds)
	// Log ruler query stats.
	logMessage := append([]interface{}{
	"msg", "ruler query stats",
	"cortex_ruler_query_seconds_total", querySeconds,
	}, qs)
	level.Info(util_log.WithContext(ctx, logger)).Log(logMessage...)
	}()
	}
	result, err := qf(ctx, qs, t)
	return result, err
	}
	}
	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) {
	timer := prometheus.NewTimer(nil)
	defer func() {
	querySeconds := timer.ObserveDuration().Seconds()
	queryTime.Add(querySeconds)
	level.Info(util_log.WithContext(ctx, logger)).Log("msg", "ruler query stats", "cortex_ruler_query_seconds_total", querySeconds, "query", qs)
	}()
	result, err := qf(ctx, qs, t)
	return result, err
	}
	}

[treid314]

not sure what's going on with logging here, but we can just call Log, right?

I'm trying to follow what we do for query front-end logging in case a user would also want to record this log message in the ruler and use it for billing instead of the added metric.

[tomwilkie]

LGTM! Not going to merge until @pstibrany has had a chance to see the changes.