Skip to content

Commit

Permalink
Store metrics queueTime in seconds (#5052)
Browse files Browse the repository at this point in the history
* Store metrics queueTime in seconds

* Address comments

* Helper function to convert seconds to nanoseconds
  • Loading branch information
ssncferreira authored Jan 6, 2022
1 parent c03614e commit 191a8a6
Show file tree
Hide file tree
Showing 12 changed files with 98 additions and 92 deletions.
2 changes: 1 addition & 1 deletion docs/sources/api/_index.md
Original file line number Diff line number Diff line change
Expand Up @@ -939,9 +939,9 @@ The example belows show all possible statistics returned with their respective d
},
"summary": {
"bytesProcessedPerSecond": 0, // Total of bytes processed per second
"queueTime": 0, // Total queue time in nanoseconds (int)
"execTime": 0, // Total execution time in seconds (float)
"linesProcessedPerSecond": 0, // Total lines processed per second
"queueTime": 0, // Total queue time in seconds (float)
"totalBytesProcessed":0, // Total amount of bytes processed overall for this request
"totalLinesProcessed":0 // Total amount of lines processed overall for this request
}
Expand Down
2 changes: 1 addition & 1 deletion pkg/logql/engine_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -2075,7 +2075,7 @@ func TestEngine_Stats(t *testing.T) {
r, err := q.Exec(user.InjectOrgID(ctx, "fake"))
require.NoError(t, err)
require.Equal(t, int64(1), r.Statistics.TotalDecompressedBytes())
require.Equal(t, queueTime.Nanoseconds(), r.Statistics.Summary.QueueTime)
require.Equal(t, queueTime.Seconds(), r.Statistics.Summary.QueueTime)
}

type errorIteratorQuerier struct {
Expand Down
9 changes: 4 additions & 5 deletions pkg/logql/metrics.go
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,6 @@ package logql
import (
"context"
"strings"
"time"

util_log "github.com/cortexproject/cortex/pkg/util/log"
"github.com/dustin/go-humanize"
Expand All @@ -13,7 +12,7 @@ import (
promql_parser "github.com/prometheus/prometheus/promql/parser"

"github.com/grafana/loki/pkg/logqlmodel"
"github.com/grafana/loki/pkg/logqlmodel/stats"
logql_stats "github.com/grafana/loki/pkg/logqlmodel/stats"
"github.com/grafana/loki/pkg/util/httpreq"
)

Expand Down Expand Up @@ -67,7 +66,7 @@ var (
})
)

func RecordMetrics(ctx context.Context, p Params, status string, stats stats.Result, result promql_parser.Value) {
func RecordMetrics(ctx context.Context, p Params, status string, stats logql_stats.Result, result promql_parser.Value) {
var (
logger = util_log.WithContext(ctx, util_log.Logger)
rt = string(GetRangeType(p))
Expand Down Expand Up @@ -100,13 +99,13 @@ func RecordMetrics(ctx context.Context, p Params, status string, stats stats.Res
"range_type", rt,
"length", p.End().Sub(p.Start()),
"step", p.Step(),
"duration", time.Duration(int64(stats.Summary.ExecTime * float64(time.Second))),
"duration", logql_stats.ConvertSecondsToNanoseconds(stats.Summary.ExecTime),
"status", status,
"limit", p.Limit(),
"returned_lines", returnedLines,
"throughput", strings.Replace(humanize.Bytes(uint64(stats.Summary.BytesProcessedPerSecond)), " ", "", 1),
"total_bytes", strings.Replace(humanize.Bytes(uint64(stats.Summary.TotalBytesProcessed)), " ", "", 1),
"queue_time", time.Duration(stats.Summary.QueueTime),
"queue_time", logql_stats.ConvertSecondsToNanoseconds(stats.Summary.QueueTime),
}...)

logValues = append(logValues, tagsToKeyValues(queryTags)...)
Expand Down
2 changes: 1 addition & 1 deletion pkg/logql/metrics_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -76,7 +76,7 @@ func TestLogSlowQuery(t *testing.T) {
}, "200", stats.Result{
Summary: stats.Summary{
BytesProcessedPerSecond: 100000,
QueueTime: 2,
QueueTime: 0.000000002,
ExecTime: 25.25,
TotalBytesProcessed: 100000,
},
Expand Down
16 changes: 11 additions & 5 deletions pkg/logqlmodel/stats/context.go
Original file line number Diff line number Diff line change
Expand Up @@ -140,7 +140,7 @@ func (r *Result) ComputeSummary(execTime time.Duration, queueTime time.Duration)
execTime.Seconds())
}
if queueTime != 0 {
r.Summary.QueueTime = int64(queueTime)
r.Summary.QueueTime = queueTime.Seconds()
}
}

Expand Down Expand Up @@ -171,8 +171,14 @@ func (i *Ingester) Merge(m Ingester) {
func (r *Result) Merge(m Result) {
r.Querier.Merge(m.Querier)
r.Ingester.Merge(m.Ingester)
r.ComputeSummary(time.Duration(int64((r.Summary.ExecTime+m.Summary.ExecTime)*float64(time.Second))),
time.Duration(r.Summary.QueueTime+m.Summary.QueueTime))
r.ComputeSummary(ConvertSecondsToNanoseconds(r.Summary.ExecTime+m.Summary.ExecTime),
ConvertSecondsToNanoseconds(r.Summary.QueueTime+m.Summary.QueueTime))
}

// ConvertSecondsToNanoseconds converts time.Duration representation of seconds (float64)
// into time.Duration representation of nanoseconds (int64)
func ConvertSecondsToNanoseconds(seconds float64) time.Duration {
return time.Duration(int64(seconds * float64(time.Second)))
}

func (r Result) ChunksDownloadTime() time.Duration {
Expand Down Expand Up @@ -284,7 +290,7 @@ func (s Summary) Log(log log.Logger) {
"Summary.LinesProcessedPerSecond", s.LinesProcessedPerSecond,
"Summary.TotalBytesProcessed", humanize.Bytes(uint64(s.TotalBytesProcessed)),
"Summary.TotalLinesProcessed", s.TotalLinesProcessed,
"Summary.ExecTime", time.Duration(int64(s.ExecTime*float64(time.Second))),
"Summary.QueueTime", time.Duration(s.QueueTime),
"Summary.ExecTime", ConvertSecondsToNanoseconds(s.ExecTime),
"Summary.QueueTime", ConvertSecondsToNanoseconds(s.QueueTime),
)
}
8 changes: 4 additions & 4 deletions pkg/logqlmodel/stats/context_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -61,7 +61,7 @@ func TestResult(t *testing.T) {
},
Summary: Summary{
ExecTime: 2 * time.Second.Seconds(),
QueueTime: 2 * time.Nanosecond.Nanoseconds(),
QueueTime: 2 * time.Nanosecond.Seconds(),
BytesProcessedPerSecond: int64(42),
LinesProcessedPerSecond: int64(50),
TotalBytesProcessed: int64(84),
Expand Down Expand Up @@ -107,7 +107,7 @@ func TestSnapshot_JoinResults(t *testing.T) {
},
Summary: Summary{
ExecTime: 2 * time.Second.Seconds(),
QueueTime: 2 * time.Nanosecond.Nanoseconds(),
QueueTime: 2 * time.Nanosecond.Seconds(),
BytesProcessedPerSecond: int64(42),
LinesProcessedPerSecond: int64(50),
TotalBytesProcessed: int64(84),
Expand Down Expand Up @@ -179,7 +179,7 @@ func TestResult_Merge(t *testing.T) {
},
Summary: Summary{
ExecTime: 2 * time.Second.Seconds(),
QueueTime: 2 * time.Nanosecond.Nanoseconds(),
QueueTime: 2 * time.Nanosecond.Seconds(),
BytesProcessedPerSecond: int64(42),
LinesProcessedPerSecond: int64(50),
TotalBytesProcessed: int64(84),
Expand Down Expand Up @@ -226,7 +226,7 @@ func TestResult_Merge(t *testing.T) {
},
Summary: Summary{
ExecTime: 2 * 2 * time.Second.Seconds(),
QueueTime: 2 * 2 * time.Nanosecond.Nanoseconds(),
QueueTime: 2 * 2 * time.Nanosecond.Seconds(),
BytesProcessedPerSecond: int64(42), // 2 requests at the same pace should give the same bytes/lines per sec
LinesProcessedPerSecond: int64(50),
TotalBytesProcessed: 2 * int64(84),
Expand Down
131 changes: 64 additions & 67 deletions pkg/logqlmodel/stats/stats.pb.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

8 changes: 6 additions & 2 deletions pkg/logqlmodel/stats/stats.proto
Original file line number Diff line number Diff line change
Expand Up @@ -27,9 +27,13 @@ message Summary {
// Total lines processed.
int64 totalLinesProcessed = 4 [(gogoproto.jsontag) = "totalLinesProcessed"];
// Execution time in seconds.
// In addition to internal calculations this is also returned by the HTTP API.
// Grafana expects time values to be returned in seconds as float.
double execTime = 5 [(gogoproto.jsontag) = "execTime"];
// Queue time in nanoseconds.
int64 queueTime = 6 [(gogoproto.jsontag) = "queueTime"];
// Queue time in seconds.
// In addition to internal calculations this is also returned by the HTTP API.
// Grafana expects time values to be returned in seconds as float.
double queueTime = 6 [(gogoproto.jsontag) = "queueTime"];
}

message Querier {
Expand Down
2 changes: 1 addition & 1 deletion pkg/querier/queryrange/codec_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -903,9 +903,9 @@ var (
},
"summary": {
"bytesProcessedPerSecond": 20,
"queueTime": 21,
"execTime": 22,
"linesProcessedPerSecond": 23,
"queueTime": 21,
"totalBytesProcessed": 24,
"totalLinesProcessed": 25
}
Expand Down
2 changes: 1 addition & 1 deletion pkg/querier/queryrange/prometheus_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -49,9 +49,9 @@ var emptyStats = `"stats": {
},
"summary": {
"bytesProcessedPerSecond": 0,
"queueTime": 0,
"execTime": 0,
"linesProcessedPerSecond": 0,
"queueTime": 0,
"totalBytesProcessed":0,
"totalLinesProcessed":0
}
Expand Down
2 changes: 1 addition & 1 deletion pkg/util/marshal/legacy/marshal_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -80,9 +80,9 @@ var queryTests = []struct {
},
"summary": {
"bytesProcessedPerSecond": 0,
"queueTime": 0,
"execTime": 0,
"linesProcessedPerSecond": 0,
"queueTime": 0,
"totalBytesProcessed":0,
"totalLinesProcessed":0
}
Expand Down
Loading

0 comments on commit 191a8a6

Please sign in to comment.