Skip to content

Commit 1e064f0

Browse files
SungJin1212SungJin1212
committed
Add query response series log
Signed-off-by: SungJin1212 <[email protected]>
1 parent fbd81bb commit 1e064f0

File tree

7 files changed

+71
-24
lines changed

7 files changed

+71
-24
lines changed

‎CHANGELOG.md

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@
1717
* [FEATURE] Chunk Cache: Support multi level cache and add metrics. #6249
1818
* [FEATURE] Distributor: Accept multiple HA Tracker pairs in the same request. #6256
1919
* [FEATURE] Ruler: Add support for per-user external labels #6340
20+
* [ENHANCEMENT] Query Frontend: Add a # of series in query response to query stat log. #6423
2021
* [ENHANCEMENT] Store Gateway: Add a hedged request to reduce the tail latency. #6388
2122
* [ENHANCEMENT] Ingester: Add metrics to track succeed/failed native histograms. #6370
2223
* [ENHANCEMENT] Query Frontend/Querier: Add an experimental flag `-querier.enable-promql-experimental-functions` to enable experimental promQL functions. #6355

‎pkg/frontend/transport/handler.go

Lines changed: 13 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -90,7 +90,7 @@ type Handler struct {
9090

9191
// Metrics.
9292
querySeconds *prometheus.CounterVec
93-
querySeries *prometheus.CounterVec
93+
queryFetchedSeries *prometheus.CounterVec
9494
queryFetchedSamples *prometheus.CounterVec
9595
queryScannedSamples *prometheus.CounterVec
9696
queryPeakSamples *prometheus.HistogramVec
@@ -114,7 +114,7 @@ func NewHandler(cfg HandlerConfig, roundTripper http.RoundTripper, log log.Logge
114114
Help: "Total amount of wall clock time spend processing queries.",
115115
}, []string{"user"})
116116

117-
h.querySeries = promauto.With(reg).NewCounterVec(prometheus.CounterOpts{
117+
h.queryFetchedSeries = promauto.With(reg).NewCounterVec(prometheus.CounterOpts{
118118
Name: "cortex_query_fetched_series_total",
119119
Help: "Number of series fetched to execute a query.",
120120
}, []string{"user"})
@@ -158,7 +158,7 @@ func NewHandler(cfg HandlerConfig, roundTripper http.RoundTripper, log log.Logge
158158

159159
h.activeUsers = util.NewActiveUsersCleanupWithDefaultValues(func(user string) {
160160
h.querySeconds.DeleteLabelValues(user)
161-
h.querySeries.DeleteLabelValues(user)
161+
h.queryFetchedSeries.DeleteLabelValues(user)
162162
h.queryFetchedSamples.DeleteLabelValues(user)
163163
h.queryScannedSamples.DeleteLabelValues(user)
164164
h.queryPeakSamples.DeleteLabelValues(user)
@@ -338,9 +338,10 @@ func (f *Handler) reportSlowQuery(r *http.Request, queryString url.Values, query
338338
func (f *Handler) reportQueryStats(r *http.Request, userID string, queryString url.Values, queryResponseTime time.Duration, stats *querier_stats.QueryStats, error error, statusCode int, resp *http.Response) {
339339
wallTime := stats.LoadWallTime()
340340
queryStorageWallTime := stats.LoadQueryStorageWallTime()
341-
numSeries := stats.LoadFetchedSeries()
342-
numChunks := stats.LoadFetchedChunks()
343-
numSamples := stats.LoadFetchedSamples()
341+
numResponseSeries := stats.LoadResponseSeries()
342+
numFetchedSeries := stats.LoadFetchedSeries()
343+
numFetchedChunks := stats.LoadFetchedChunks()
344+
numFetchedSamples := stats.LoadFetchedSamples()
344345
numScannedSamples := stats.LoadScannedSamples()
345346
numPeakSamples := stats.LoadPeakSamples()
346347
numChunkBytes := stats.LoadFetchedChunkBytes()
@@ -353,8 +354,8 @@ func (f *Handler) reportQueryStats(r *http.Request, userID string, queryString u
353354

354355
// Track stats.
355356
f.querySeconds.WithLabelValues(userID).Add(wallTime.Seconds())
356-
f.querySeries.WithLabelValues(userID).Add(float64(numSeries))
357-
f.queryFetchedSamples.WithLabelValues(userID).Add(float64(numSamples))
357+
f.queryFetchedSeries.WithLabelValues(userID).Add(float64(numFetchedSeries))
358+
f.queryFetchedSamples.WithLabelValues(userID).Add(float64(numFetchedSamples))
358359
f.queryScannedSamples.WithLabelValues(userID).Add(float64(numScannedSamples))
359360
f.queryPeakSamples.WithLabelValues(userID).Observe(float64(numPeakSamples))
360361
f.queryChunkBytes.WithLabelValues(userID).Add(float64(numChunkBytes))
@@ -378,9 +379,10 @@ func (f *Handler) reportQueryStats(r *http.Request, userID string, queryString u
378379
"path", r.URL.Path,
379380
"response_time", queryResponseTime,
380381
"query_wall_time_seconds", wallTime.Seconds(),
381-
"fetched_series_count", numSeries,
382-
"fetched_chunks_count", numChunks,
383-
"fetched_samples_count", numSamples,
382+
"response_series_count", numResponseSeries,
383+
"fetched_series_count", numFetchedSeries,
384+
"fetched_chunks_count", numFetchedChunks,
385+
"fetched_samples_count", numFetchedSamples,
384386
"fetched_chunks_bytes", numChunkBytes,
385387
"fetched_data_bytes", numDataBytes,
386388
"split_queries", splitQueries,

‎pkg/frontend/transport/handler_test.go

Lines changed: 10 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -429,14 +429,15 @@ func TestReportQueryStatsFormat(t *testing.T) {
429429

430430
tests := map[string]testCase{
431431
"should not include query and header details if empty": {
432-
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000`,
432+
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 response_series_count=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000`,
433433
},
434434
"should include query length and string at the end": {
435435
queryString: url.Values(map[string][]string{"query": {"up"}}),
436-
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000 query_length=2 param_query=up`,
436+
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 response_series_count=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000 query_length=2 param_query=up`,
437437
},
438438
"should include query stats": {
439439
queryStats: &querier_stats.QueryStats{
440+
QueryResponseSeries: 100,
440441
Stats: querier_stats.Stats{
441442
WallTime: 3 * time.Second,
442443
QueryStorageWallTime: 100 * time.Minute,
@@ -448,34 +449,35 @@ func TestReportQueryStatsFormat(t *testing.T) {
448449
SplitQueries: 10,
449450
},
450451
},
451-
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=3 fetched_series_count=100 fetched_chunks_count=200 fetched_samples_count=300 fetched_chunks_bytes=1024 fetched_data_bytes=2048 split_queries=10 status_code=200 response_size=1000 query_storage_wall_time_seconds=6000`,
452+
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=3 response_series_count=100 fetched_series_count=100 fetched_chunks_count=200 fetched_samples_count=300 fetched_chunks_bytes=1024 fetched_data_bytes=2048 split_queries=10 status_code=200 response_size=1000 query_storage_wall_time_seconds=6000`,
452453
},
453454
"should include user agent": {
454455
header: http.Header{"User-Agent": []string{"Grafana"}},
455-
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000 user_agent=Grafana`,
456+
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 response_series_count=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000 user_agent=Grafana`,
456457
},
457458
"should include response error": {
458459
responseErr: errors.New("foo_err"),
459-
expectedLog: `level=error msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000 error=foo_err`,
460+
expectedLog: `level=error msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 response_series_count=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000 error=foo_err`,
460461
},
461462
"should include query priority": {
462463
queryString: url.Values(map[string][]string{"query": {"up"}}),
463464
queryStats: &querier_stats.QueryStats{
464465
Priority: 99,
465466
PriorityAssigned: true,
466467
},
467-
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000 query_length=2 priority=99 param_query=up`,
468+
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 response_series_count=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000 query_length=2 priority=99 param_query=up`,
468469
},
469470
"should include data fetch min and max time": {
470471
queryString: url.Values(map[string][]string{"query": {"up"}}),
471472
queryStats: &querier_stats.QueryStats{
472473
DataSelectMaxTime: 1704153600000,
473474
DataSelectMinTime: 1704067200000,
474475
},
475-
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000 data_select_max_time=1704153600 data_select_min_time=1704067200 query_length=2 param_query=up`,
476+
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=0 response_series_count=0 fetched_series_count=0 fetched_chunks_count=0 fetched_samples_count=0 fetched_chunks_bytes=0 fetched_data_bytes=0 split_queries=0 status_code=200 response_size=1000 data_select_max_time=1704153600 data_select_min_time=1704067200 query_length=2 param_query=up`,
476477
},
477478
"should include query stats with store gateway stats": {
478479
queryStats: &querier_stats.QueryStats{
480+
QueryResponseSeries: 100,
479481
Stats: querier_stats.Stats{
480482
WallTime: 3 * time.Second,
481483
QueryStorageWallTime: 100 * time.Minute,
@@ -489,7 +491,7 @@ func TestReportQueryStatsFormat(t *testing.T) {
489491
StoreGatewayTouchedPostingBytes: 200,
490492
},
491493
},
492-
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=3 fetched_series_count=100 fetched_chunks_count=200 fetched_samples_count=300 fetched_chunks_bytes=1024 fetched_data_bytes=2048 split_queries=10 status_code=200 response_size=1000 store_gateway_touched_postings_count=20 store_gateway_touched_posting_bytes=200 query_storage_wall_time_seconds=6000`,
494+
expectedLog: `level=info msg="query stats" component=query-frontend method=GET path=/prometheus/api/v1/query response_time=1s query_wall_time_seconds=3 response_series_count=100 fetched_series_count=100 fetched_chunks_count=200 fetched_samples_count=300 fetched_chunks_bytes=1024 fetched_data_bytes=2048 split_queries=10 status_code=200 response_size=1000 store_gateway_touched_postings_count=20 store_gateway_touched_posting_bytes=200 query_storage_wall_time_seconds=6000`,
493495
},
494496
}
495497

‎pkg/querier/stats/stats.go

Lines changed: 22 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -16,11 +16,12 @@ var ctxKey = contextKey(0)
1616

1717
type QueryStats struct {
1818
Stats
19-
PriorityAssigned bool
20-
Priority int64
21-
DataSelectMaxTime int64
22-
DataSelectMinTime int64
23-
m sync.Mutex
19+
QueryResponseSeries uint64
20+
PriorityAssigned bool
21+
Priority int64
22+
DataSelectMaxTime int64
23+
DataSelectMinTime int64
24+
m sync.Mutex
2425
}
2526

2627
// ContextWithEmptyStats returns a context with empty stats.
@@ -65,6 +66,22 @@ func (s *QueryStats) LoadWallTime() time.Duration {
6566
return time.Duration(atomic.LoadInt64((*int64)(&s.WallTime)))
6667
}
6768

69+
func (s *QueryStats) AddResponseSeries(series uint64) {
70+
if s == nil {
71+
return
72+
}
73+
74+
atomic.AddUint64(&s.QueryResponseSeries, series)
75+
}
76+
77+
func (s *QueryStats) LoadResponseSeries() uint64 {
78+
if s == nil {
79+
return 0
80+
}
81+
82+
return atomic.LoadUint64(&s.QueryResponseSeries)
83+
}
84+
6885
func (s *QueryStats) AddFetchedSeries(series uint64) {
6986
if s == nil {
7087
return

‎pkg/querier/tripperware/instantquery/instant_query.go

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ import (
1717
"github.com/weaveworks/common/httpgrpc"
1818
"google.golang.org/grpc/status"
1919

20+
"github.com/cortexproject/cortex/pkg/querier/stats"
2021
"github.com/cortexproject/cortex/pkg/querier/tripperware"
2122
"github.com/cortexproject/cortex/pkg/util"
2223
"github.com/cortexproject/cortex/pkg/util/spanlogger"
@@ -176,6 +177,9 @@ func (instantQueryCodec) EncodeResponse(ctx context.Context, res tripperware.Res
176177
return nil, httpgrpc.Errorf(http.StatusInternalServerError, "invalid response format")
177178
}
178179

180+
queryStats := stats.FromContext(ctx)
181+
tripperware.SetQueryResponseStats(a, queryStats)
182+
179183
b, err := json.Marshal(a)
180184
if err != nil {
181185
return nil, httpgrpc.Errorf(http.StatusInternalServerError, "error encoding response: %v", err)

‎pkg/querier/tripperware/queryrange/query_range.go

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ import (
1818
"github.com/prometheus/common/model"
1919
"github.com/weaveworks/common/httpgrpc"
2020

21+
"github.com/cortexproject/cortex/pkg/querier/stats"
2122
"github.com/cortexproject/cortex/pkg/querier/tripperware"
2223
"github.com/cortexproject/cortex/pkg/util"
2324
"github.com/cortexproject/cortex/pkg/util/spanlogger"
@@ -241,6 +242,9 @@ func (prometheusCodec) EncodeResponse(ctx context.Context, res tripperware.Respo
241242
if a != nil {
242243
m := a.Data.Result.GetMatrix()
243244
sp.LogFields(otlog.Int("series", len(m.GetSampleStreams())))
245+
246+
queryStats := stats.FromContext(ctx)
247+
tripperware.SetQueryResponseStats(a, queryStats)
244248
}
245249

246250
b, err := json.Marshal(a)

‎pkg/querier/tripperware/util.go

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ import (
66

77
"github.com/weaveworks/common/httpgrpc"
88

9+
"github.com/cortexproject/cortex/pkg/querier/stats"
910
"github.com/cortexproject/cortex/pkg/tenant"
1011
"github.com/cortexproject/cortex/pkg/util/validation"
1112
)
@@ -70,3 +71,19 @@ func DoRequests(ctx context.Context, downstream Handler, reqs []Request, limits
7071

7172
return resps, firstErr
7273
}
74+
75+
func SetQueryResponseStats(a *PrometheusResponse, queryStats *stats.QueryStats) {
76+
if queryStats != nil {
77+
v := a.Data.Result.GetVector()
78+
if v != nil {
79+
queryStats.AddResponseSeries(uint64(len(v.GetSamples())))
80+
return
81+
}
82+
83+
m := a.Data.Result.GetMatrix()
84+
if m != nil {
85+
queryStats.AddResponseSeries(uint64(len(m.GetSampleStreams())))
86+
return
87+
}
88+
}
89+
}

0 commit comments

Comments
 (0)