Merge pull request #2408 from davkal/api-stats

Adds execution timer stats to the range query

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 {
@@ -328,7 +330,7 @@ func (ng *Engine) exec(ctx context.Context, q *query) (Value, error) {
 
 	const env = "query execution"
 
-	evalTimer := q.stats.GetTimer(stats.TotalEvalTime).Start()
+	evalTimer := q.stats.GetTimer(stats.EvalTotalTime).Start()
 	defer evalTimer.Stop()
 
 	// The base context might already be canceled on the first iteration (e.g. during shutdown).

util/stats/query_stats.go

@@ -19,19 +19,20 @@ type QueryTiming int
 
 // Query timings.
 const (
-	TotalEvalTime QueryTiming = iota
+	EvalTotalTime QueryTiming = iota
 	ResultSortTime
 	QueryPreparationTime
 	InnerEvalTime
 	ResultAppendTime
 	ExecQueueTime
+	ExecTotalTime
 )
 
 // Return a string representation of a QueryTiming identifier.
 func (s QueryTiming) String() string {
 	switch s {
-	case TotalEvalTime:
-		return "Total eval time"
+	case EvalTotalTime:
+		return "Eval total time"
 	case ResultSortTime:
 		return "Result sorting time"
 	case QueryPreparationTime:
@@ -42,7 +43,53 @@ 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"
 	}
 }
+
+// queryTimings with all query timers mapped to durations.
+type queryTimings struct {
+	EvalTotalTime        float64 `json:"evalTotalTime"`
+	ResultSortTime       float64 `json:"resultSortTime"`
+	QueryPreparationTime float64 `json:"queryPreparationTime"`
+	InnerEvalTime        float64 `json:"innerEvalTime"`
+	ResultAppendTime     float64 `json:"resultAppendTime"`
+	ExecQueueTime        float64 `json:"execQueueTime"`
+	ExecTotalTime        float64 `json:"execTotalTime"`
+}
+
+// QueryStats currently only holding query timings.
+type QueryStats struct {
+	Timings queryTimings `json:"timings,omitempty"`
+}
+
+// NewQueryStats makes a QueryStats struct with all QueryTimings found in the
+// given TimerGroup.
+func NewQueryStats(tg *TimerGroup) *QueryStats {
+	var qt queryTimings
+
+	for s, timer := range tg.timers {
+		switch s {
+		case EvalTotalTime:
+			qt.EvalTotalTime = timer.Duration()
+		case ResultSortTime:
+			qt.ResultSortTime = timer.Duration()
+		case QueryPreparationTime:
+			qt.QueryPreparationTime = timer.Duration()
+		case InnerEvalTime:
+			qt.InnerEvalTime = timer.Duration()
+		case ResultAppendTime:
+			qt.ResultAppendTime = timer.Duration()
+		case ExecQueueTime:
+			qt.ExecQueueTime = timer.Duration()
+		case ExecTotalTime:
+			qt.ExecTotalTime = timer.Duration()
+		}
+	}
+
+	qs := QueryStats{Timings: qt}
+	return &qs
+}

util/stats/stats_test.go

@@ -0,0 +1,62 @@
+// Copyright 2017 The Prometheus Authors
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package stats
+
+import (
+	"encoding/json"
+	"regexp"
+	"testing"
+	"time"
+)
+
+func TestTimerGroupNewTimer(t *testing.T) {
+	tg := NewTimerGroup()
+	timer := tg.GetTimer(ExecTotalTime)
+	if duration := timer.Duration(); duration != 0 {
+		t.Fatalf("Expected duration of 0, but it was %f instead.", duration)
+	}
+	minimum := 2 * time.Millisecond
+	timer.Start()
+	time.Sleep(minimum)
+	timer.Stop()
+	if duration := timer.Duration(); duration == 0 {
+		t.Fatalf("Expected duration greater than 0, but it was %f instead.", duration)
+	}
+	if elapsed := timer.ElapsedTime(); elapsed < minimum {
+		t.Fatalf("Expected elapsed time to be greater than time slept, elapsed was %d, and time slept was %d.", elapsed.Nanoseconds(), minimum)
+	}
+}
+
+func TestQueryStatsWithTimers(t *testing.T) {
+	tg := NewTimerGroup()
+	timer := tg.GetTimer(ExecTotalTime)
+	timer.Start()
+	time.Sleep(2 * time.Millisecond)
+	timer.Stop()
+
+	var qs *QueryStats
+	qs = NewQueryStats(tg)
+	actual, err := json.Marshal(qs)
+	if err != nil {
+		t.Fatalf("Unexpected error during serialization: %v", err)
+	}
+	// Timing value is one of multiple fields, unit is seconds (float).
+	match, err := regexp.MatchString(`[,{]"execTotalTime":\d+\.\d+[,}]`, string(actual))
+	if err != nil {
+		t.Fatalf("Unexpected error while matching string: %v", err)
+	}
+	if !match {
+		t.Fatalf("Expected timings with one non-zero entry, but got %s.", actual)
+	}
+}

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)

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
@@ -170,8 +171,9 @@ func (api *API) Register(r *route.Router) {
 }
 
 type queryData struct {
-	ResultType promql.ValueType `json:"resultType"`
-	Result     promql.Value     `json:"result"`
+	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) {
@@ -219,9 +221,17 @@ func (api *API) query(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.NewQueryStats(qry.Stats())
+	}
+
 	return &queryData{
 		ResultType: res.Value.Type(),
 		Result:     res.Value,
+		Stats:      qs,
 	}, nil
 }
 
@@ -284,9 +294,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.NewQueryStats(qry.Stats())
+	}
+
 	return &queryData{
 		ResultType: res.Value.Type(),
 		Result:     res.Value,
+		Stats:      qs,
 	}, nil
 }