diff --git a/promql/engine.go b/promql/engine.go index a2d6ae819..4f37ced26 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 { @@ -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). diff --git a/util/stats/query_stats.go b/util/stats/query_stats.go index 3d7ad0e83..9c0c42b32 100644 --- a/util/stats/query_stats.go +++ b/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 +} diff --git a/util/stats/stats_test.go b/util/stats/stats_test.go new file mode 100644 index 000000000..3f82885ce --- /dev/null +++ b/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) + } +} 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..825e8db72 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 @@ -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 }