From c93e54d240db26595c230150cc082d086feebdb2 Mon Sep 17 00:00:00 2001
From: David Kaltschmidt <david.kaltschmidt@gmail.com>
Date: Wed, 8 Feb 2017 12:58:40 +0100
Subject: [PATCH] Adds execution timer stats to the range query

API consumers should be able to get insight into the query run times.
The UI currently measures total roundtrip times. This PR allows for more
fine grained metrics to be exposed.

* adds new timer for total execution time (queue + eval)

* expose new timer, queue timer, and eval timer in stats field of the
 range query response:
```json
{
  "status": "success",
  "data": {
    "resultType": "matrix",
    "result": [],
    "stats": {
      "execQueueTimeNs": 4683,
      "execTotalTimeNs": 2086587,
      "totalEvalTimeNs": 2077851
    }
  }
}
```

* stats field is optional, only set when query parameter `stats` is not
empty

Try it via
```sh
curl 'http://localhost:9090/api/v1/query_range?query=up&start=1486480279&end=1486483879&step=14000&stats=true'
```

Review feedback

* moved query stats json generation to query_stats.go
* use seconds for all query timers
* expose all timers available
* Changed ExecTotalTime string representation from Exec queue total time to Exec total time
---
 promql/engine.go          |  2 ++
 util/stats/query_stats.go | 41 +++++++++++++++++++++++++++++++++++++++
 util/stats/timer.go       |  5 +++++
 web/api/v1/api.go         |  9 +++++++++
 4 files changed, 57 insertions(+)

diff --git a/promql/engine.go b/promql/engine.go
index a2d6ae819..b9775d210 100644
--- a/promql/engine.go
+++ b/promql/engine.go
@@ -314,6 +314,8 @@ func (ng *Engine) exec(ctx context.Context, q *query) (Value, error) {
 	ctx, cancel := context.WithTimeout(ctx, ng.options.Timeout)
 	q.cancel = cancel
 
+	execTimer := q.stats.GetTimer(stats.ExecTotalTime).Start()
+	defer execTimer.Stop()
 	queueTimer := q.stats.GetTimer(stats.ExecQueueTime).Start()
 
 	if err := ng.gate.Start(ctx); err != nil {
diff --git a/util/stats/query_stats.go b/util/stats/query_stats.go
index 3d7ad0e83..8c75c6568 100644
--- a/util/stats/query_stats.go
+++ b/util/stats/query_stats.go
@@ -25,6 +25,7 @@ const (
 	InnerEvalTime
 	ResultAppendTime
 	ExecQueueTime
+	ExecTotalTime
 )
 
 // Return a string representation of a QueryTiming identifier.
@@ -42,7 +43,47 @@ func (s QueryTiming) String() string {
 		return "Result append time"
 	case ExecQueueTime:
 		return "Exec queue wait time"
+	case ExecTotalTime:
+		return "Exec total time"
 	default:
 		return "Unknown query timing"
 	}
 }
+
+// QueryStats with all query timers mapped to durations.
+type QueryStats struct {
+	TotalEvalTime        float64 `json:"totalEvalTime"`
+	ResultSortTime       float64 `json:"resultSortTime"`
+	QueryPreparationTime float64 `json:"queryPreparationTime"`
+	InnerEvalTime        float64 `json:"innerEvalTime"`
+	ResultAppendTime     float64 `json:"resultAppendTime"`
+	ExecQueueTime        float64 `json:"execQueueTime"`
+	ExecTotalTime        float64 `json:"execTotalTime"`
+}
+
+// MakeQueryStats makes a QueryStats struct with all QueryTimings found in the
+// given TimerGroup.
+func MakeQueryStats(tg *TimerGroup) *QueryStats {
+	var qs QueryStats
+
+	for s, timer := range tg.timers {
+		switch s {
+		case TotalEvalTime:
+			qs.TotalEvalTime = timer.Duration()
+		case ResultSortTime:
+			qs.ResultSortTime = timer.Duration()
+		case QueryPreparationTime:
+			qs.QueryPreparationTime = timer.Duration()
+		case InnerEvalTime:
+			qs.InnerEvalTime = timer.Duration()
+		case ResultAppendTime:
+			qs.ResultAppendTime = timer.Duration()
+		case ExecQueueTime:
+			qs.ExecQueueTime = timer.Duration()
+		case ExecTotalTime:
+			qs.ExecTotalTime = timer.Duration()
+		}
+	}
+
+	return &qs
+}
diff --git a/util/stats/timer.go b/util/stats/timer.go
index 3d3ee7309..75f5868e6 100644
--- a/util/stats/timer.go
+++ b/util/stats/timer.go
@@ -45,6 +45,11 @@ func (t *Timer) ElapsedTime() time.Duration {
 	return time.Since(t.start)
 }
 
+// Duration returns the duration value of the timer in seconds.
+func (t *Timer) Duration() float64 {
+	return t.duration.Seconds()
+}
+
 // Return a string representation of the Timer.
 func (t *Timer) String() string {
 	return fmt.Sprintf("%s: %s", t.name, t.duration)
diff --git a/web/api/v1/api.go b/web/api/v1/api.go
index 122b40684..d1b058847 100644
--- a/web/api/v1/api.go
+++ b/web/api/v1/api.go
@@ -38,6 +38,7 @@ import (
 	"github.com/prometheus/prometheus/storage"
 	"github.com/prometheus/prometheus/storage/remote"
 	"github.com/prometheus/prometheus/util/httputil"
+	"github.com/prometheus/prometheus/util/stats"
 )
 
 type status string
@@ -172,6 +173,7 @@ func (api *API) Register(r *route.Router) {
 type queryData struct {
 	ResultType promql.ValueType `json:"resultType"`
 	Result     promql.Value     `json:"result"`
+	Stats      *stats.QueryStats `json:"stats,omitempty"`
 }
 
 func (api *API) options(r *http.Request) (interface{}, *apiError) {
@@ -284,9 +286,16 @@ func (api *API) queryRange(r *http.Request) (interface{}, *apiError) {
 		return nil, &apiError{errorExec, res.Err}
 	}
 
+	// Optional stats field in response if parameter "stats" is not empty.
+	var qs *stats.QueryStats
+	if r.FormValue("stats") != "" {
+		qs = stats.MakeQueryStats(qry.Stats())
+	}
+
 	return &queryData{
 		ResultType: res.Value.Type(),
 		Result:     res.Value,
+		Stats:      qs,
 	}, nil
 }