From 9453241df70784d5b5608091c8d79670038f165b Mon Sep 17 00:00:00 2001 From: Ben Ye Date: Mon, 4 Mar 2024 23:17:26 -0800 Subject: [PATCH 1/2] add storage wall time to querier stats Signed-off-by: Ben Ye --- pkg/frontend/transport/handler.go | 6 ++ pkg/frontend/transport/handler_test.go | 17 ++-- pkg/querier/querier.go | 33 +++++-- pkg/querier/stats/stats.go | 19 ++++ pkg/querier/stats/stats.pb.go | 131 ++++++++++++++++++------- pkg/querier/stats/stats.proto | 2 + pkg/querier/stats/stats_test.go | 27 +++++ pkg/ruler/compat.go | 1 + 8 files changed, 183 insertions(+), 53 deletions(-) diff --git a/pkg/frontend/transport/handler.go b/pkg/frontend/transport/handler.go index 2845198975..72d4a1564c 100644 --- a/pkg/frontend/transport/handler.go +++ b/pkg/frontend/transport/handler.go @@ -289,6 +289,7 @@ func (f *Handler) reportSlowQuery(r *http.Request, queryString url.Values, query 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) { wallTime := stats.LoadWallTime() + queryStorageWallTime := stats.LoadQueryStorageWallTime() numSeries := stats.LoadFetchedSeries() numChunks := stats.LoadFetchedChunks() numSamples := stats.LoadFetchedSamples() @@ -356,6 +357,11 @@ func (f *Handler) reportQueryStats(r *http.Request, userID string, queryString u if priority, ok := stats.LoadPriority(); ok { logMessage = append(logMessage, "priority", priority) } + if sws := queryStorageWallTime.Seconds(); sws > 0 { + // Only include query storage wall time field if set. This value can be 0 + // for query APIs that don't call `Querier` interface. + logMessage = append(logMessage, "query_storage_wall_time_seconds", sws) + } if error != nil { s, ok := status.FromError(error) diff --git a/pkg/frontend/transport/handler_test.go b/pkg/frontend/transport/handler_test.go index 425369ac3e..4b84ebe9c4 100644 --- a/pkg/frontend/transport/handler_test.go +++ b/pkg/frontend/transport/handler_test.go @@ -326,16 +326,17 @@ func TestReportQueryStatsFormat(t *testing.T) { "should include query stats": { queryStats: &querier_stats.QueryStats{ Stats: querier_stats.Stats{ - WallTime: 3 * time.Second, - FetchedSeriesCount: 100, - FetchedChunksCount: 200, - FetchedSamplesCount: 300, - FetchedChunkBytes: 1024, - FetchedDataBytes: 2048, - SplitQueries: 10, + WallTime: 3 * time.Second, + QueryStorageWallTime: 100 * time.Minute, + FetchedSeriesCount: 100, + FetchedChunksCount: 200, + FetchedSamplesCount: 300, + FetchedChunkBytes: 1024, + FetchedDataBytes: 2048, + SplitQueries: 10, }, }, - 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`, + 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`, }, "should include user agent": { header: http.Header{"User-Agent": []string{"Grafana"}}, diff --git a/pkg/querier/querier.go b/pkg/querier/querier.go index 0027507bea..29247e3cf7 100644 --- a/pkg/querier/querier.go +++ b/pkg/querier/querier.go @@ -30,6 +30,7 @@ import ( "github.com/cortexproject/cortex/pkg/querier/iterators" "github.com/cortexproject/cortex/pkg/querier/lazyquery" seriesset "github.com/cortexproject/cortex/pkg/querier/series" + querier_stats "github.com/cortexproject/cortex/pkg/querier/stats" "github.com/cortexproject/cortex/pkg/tenant" "github.com/cortexproject/cortex/pkg/util" "github.com/cortexproject/cortex/pkg/util/flagext" @@ -284,10 +285,11 @@ type querier struct { limiterHolder *limiterHolder } -func (q querier) setupFromCtx(ctx context.Context) (context.Context, string, int64, int64, storage.Querier, []storage.Querier, error) { +func (q querier) setupFromCtx(ctx context.Context) (context.Context, *querier_stats.QueryStats, string, int64, int64, storage.Querier, []storage.Querier, error) { + stats := querier_stats.FromContext(ctx) userID, err := tenant.TenantID(ctx) if err != nil { - return ctx, userID, 0, 0, nil, nil, err + return ctx, stats, userID, 0, 0, nil, nil, err } q.limiterHolder.limiterInitializer.Do(func() { @@ -298,12 +300,12 @@ func (q querier) setupFromCtx(ctx context.Context) (context.Context, string, int mint, maxt, err := validateQueryTimeRange(ctx, userID, q.mint, q.maxt, q.limits, q.maxQueryIntoFuture) if err != nil { - return ctx, userID, 0, 0, nil, nil, err + return ctx, stats, userID, 0, 0, nil, nil, err } dqr, err := q.distributor.Querier(mint, maxt) if err != nil { - return ctx, userID, 0, 0, nil, nil, err + return ctx, stats, userID, 0, 0, nil, nil, err } metadataQuerier := dqr @@ -319,23 +321,27 @@ func (q querier) setupFromCtx(ctx context.Context) (context.Context, string, int cqr, err := s.Querier(mint, maxt) if err != nil { - return ctx, userID, 0, 0, nil, nil, err + return ctx, stats, userID, 0, 0, nil, nil, err } queriers = append(queriers, cqr) } - return ctx, userID, mint, maxt, metadataQuerier, queriers, nil + return ctx, stats, userID, mint, maxt, metadataQuerier, queriers, nil } // Select implements storage.Querier interface. // The bool passed is ignored because the series is always sorted. func (q querier) Select(ctx context.Context, sortSeries bool, sp *storage.SelectHints, matchers ...*labels.Matcher) storage.SeriesSet { - ctx, userID, mint, maxt, metadataQuerier, queriers, err := q.setupFromCtx(ctx) + ctx, stats, userID, mint, maxt, metadataQuerier, queriers, err := q.setupFromCtx(ctx) if err == errEmptyTimeRange { return storage.EmptySeriesSet() } else if err != nil { return storage.ErrSeriesSet(err) } + startT := time.Now() + defer func() { + stats.AddQueryStorageWallTime(time.Since(startT)) + }() log, ctx := spanlogger.New(ctx, "querier.Select") defer log.Span.Finish() @@ -426,12 +432,17 @@ func (q querier) Select(ctx context.Context, sortSeries bool, sp *storage.Select // LabelValues implements storage.Querier. func (q querier) LabelValues(ctx context.Context, name string, matchers ...*labels.Matcher) ([]string, annotations.Annotations, error) { - ctx, _, _, _, metadataQuerier, queriers, err := q.setupFromCtx(ctx) + ctx, stats, _, _, _, metadataQuerier, queriers, err := q.setupFromCtx(ctx) if err == errEmptyTimeRange { return nil, nil, nil } else if err != nil { return nil, nil, err } + startT := time.Now() + defer func() { + stats.AddQueryStorageWallTime(time.Since(startT)) + }() + if !q.queryStoreForLabels { return metadataQuerier.LabelValues(ctx, name, matchers...) } @@ -475,12 +486,16 @@ func (q querier) LabelValues(ctx context.Context, name string, matchers ...*labe } func (q querier) LabelNames(ctx context.Context, matchers ...*labels.Matcher) ([]string, annotations.Annotations, error) { - ctx, _, _, _, metadataQuerier, queriers, err := q.setupFromCtx(ctx) + ctx, stats, _, _, _, metadataQuerier, queriers, err := q.setupFromCtx(ctx) if err == errEmptyTimeRange { return nil, nil, nil } else if err != nil { return nil, nil, err } + startT := time.Now() + defer func() { + stats.AddQueryStorageWallTime(time.Since(startT)) + }() if !q.queryStoreForLabels { return metadataQuerier.LabelNames(ctx, matchers...) diff --git a/pkg/querier/stats/stats.go b/pkg/querier/stats/stats.go index 67ec874ef3..5fd3fb3122 100644 --- a/pkg/querier/stats/stats.go +++ b/pkg/querier/stats/stats.go @@ -184,6 +184,24 @@ func (s *QueryStats) LoadFetchedChunks() uint64 { return atomic.LoadUint64(&s.FetchedChunksCount) } +// AddQueryStorageWallTime adds some time to the counter. +func (s *QueryStats) AddQueryStorageWallTime(t time.Duration) { + if s == nil { + return + } + + atomic.AddInt64((*int64)(&s.QueryStorageWallTime), int64(t)) +} + +// LoadQueryStorageWallTime returns current query storage wall time. +func (s *QueryStats) LoadQueryStorageWallTime() time.Duration { + if s == nil { + return 0 + } + + return time.Duration(atomic.LoadInt64((*int64)(&s.QueryStorageWallTime))) +} + func (s *QueryStats) AddSplitQueries(count uint64) { if s == nil { return @@ -259,6 +277,7 @@ func (s *QueryStats) Merge(other *QueryStats) { } s.AddWallTime(other.LoadWallTime()) + s.AddQueryStorageWallTime(other.LoadQueryStorageWallTime()) s.AddFetchedSeries(other.LoadFetchedSeries()) s.AddFetchedChunkBytes(other.LoadFetchedChunkBytes()) s.AddFetchedDataBytes(other.LoadFetchedDataBytes()) diff --git a/pkg/querier/stats/stats.pb.go b/pkg/querier/stats/stats.pb.go index a50af9a64a..ebbcf9b237 100644 --- a/pkg/querier/stats/stats.pb.go +++ b/pkg/querier/stats/stats.pb.go @@ -51,6 +51,8 @@ type Stats struct { // The total number of split queries sent after going through all the middlewares. // It includes the number of requests that might be discarded by the queue. SplitQueries uint64 `protobuf:"varint,9,opt,name=split_queries,json=splitQueries,proto3" json:"split_queries,omitempty"` + // The sum of wall time spent in the querier to fetch and merge data from storage. + QueryStorageWallTime time.Duration `protobuf:"bytes,10,opt,name=query_storage_wall_time,json=queryStorageWallTime,proto3,stdduration" json:"query_storage_wall_time"` } func (m *Stats) Reset() { *m = Stats{} } @@ -148,6 +150,13 @@ func (m *Stats) GetSplitQueries() uint64 { return 0 } +func (m *Stats) GetQueryStorageWallTime() time.Duration { + if m != nil { + return m.QueryStorageWallTime + } + return 0 +} + func init() { proto.RegisterType((*Stats)(nil), "stats.Stats") proto.RegisterMapType((map[string]string)(nil), "stats.Stats.ExtraFieldsEntry") @@ -156,36 +165,38 @@ func init() { func init() { proto.RegisterFile("stats.proto", fileDescriptor_b4756a0aec8b9d44) } var fileDescriptor_b4756a0aec8b9d44 = []byte{ - // 458 bytes of a gzipped FileDescriptorProto - 0x1f, 0x8b, 0x08, 0x00, 0x00, 0x00, 0x00, 0x00, 0x02, 0xff, 0x5c, 0x92, 0x31, 0x6f, 0xd3, 0x40, - 0x14, 0xc7, 0x7d, 0x4d, 0x52, 0xe2, 0x4b, 0x91, 0xc2, 0x11, 0x24, 0x37, 0x12, 0xd7, 0x00, 0x4b, - 0x06, 0xe4, 0xa0, 0xb0, 0x20, 0x90, 0x50, 0x95, 0xb6, 0x88, 0x15, 0x87, 0x89, 0xc5, 0xba, 0x24, - 0x97, 0xe4, 0x54, 0xc7, 0x17, 0xec, 0x67, 0x20, 0x1b, 0x2b, 0x1b, 0x23, 0x1f, 0x81, 0x8f, 0x92, - 0x31, 0x63, 0xa7, 0x42, 0x9c, 0x85, 0xb1, 0x1f, 0x01, 0xdd, 0x3b, 0xbb, 0xd0, 0x6e, 0xf7, 0xde, - 0xef, 0xfd, 0x9f, 0xee, 0xff, 0xbf, 0xa3, 0x8d, 0x14, 0x04, 0xa4, 0xfe, 0x32, 0xd1, 0xa0, 0x59, - 0x0d, 0x8b, 0x76, 0x6b, 0xa6, 0x67, 0x1a, 0x3b, 0x3d, 0x73, 0xb2, 0xb0, 0xcd, 0x67, 0x5a, 0xcf, - 0x22, 0xd9, 0xc3, 0x6a, 0x94, 0x4d, 0x7b, 0x93, 0x2c, 0x11, 0xa0, 0x74, 0x5c, 0xf0, 0xc3, 0xdb, - 0x5c, 0xc4, 0x2b, 0x8b, 0x1e, 0x7f, 0xab, 0xd2, 0xda, 0xd0, 0xac, 0x66, 0xc7, 0xd4, 0xfd, 0x2c, - 0xa2, 0x28, 0x04, 0xb5, 0x90, 0x1e, 0xe9, 0x90, 0x6e, 0xa3, 0x7f, 0xe8, 0x5b, 0xa1, 0x5f, 0x0a, - 0xfd, 0xd3, 0x62, 0xf1, 0xa0, 0xbe, 0xbe, 0x3c, 0x72, 0x7e, 0xfc, 0x3a, 0x22, 0x41, 0xdd, 0xa8, - 0xde, 0xab, 0x85, 0x64, 0xcf, 0x68, 0x6b, 0x2a, 0x61, 0x3c, 0x97, 0x93, 0x30, 0x95, 0x89, 0x92, - 0x69, 0x38, 0xd6, 0x59, 0x0c, 0xde, 0x5e, 0x87, 0x74, 0xab, 0x01, 0x2b, 0xd8, 0x10, 0xd1, 0x89, - 0x21, 0xcc, 0xa7, 0xf7, 0x4b, 0xc5, 0x78, 0x9e, 0xc5, 0xe7, 0xe1, 0x68, 0x05, 0x32, 0xf5, 0x2a, - 0x28, 0xb8, 0x57, 0xa0, 0x13, 0x43, 0x06, 0x06, 0xb0, 0xa7, 0xb4, 0xdc, 0x12, 0x4e, 0x04, 0x88, - 0x62, 0xbc, 0x8a, 0xe3, 0xcd, 0x82, 0x9c, 0x0a, 0x10, 0x76, 0xfa, 0x98, 0x1e, 0xc8, 0x2f, 0x90, - 0x88, 0x70, 0xaa, 0x64, 0x34, 0x49, 0xbd, 0x5a, 0xa7, 0xd2, 0x6d, 0xf4, 0x1f, 0xfa, 0x36, 0x57, - 0x74, 0xed, 0x9f, 0x99, 0x81, 0x37, 0xc8, 0xcf, 0x62, 0x48, 0x56, 0x41, 0x43, 0xfe, 0xeb, 0xfc, - 0xef, 0x08, 0xef, 0x57, 0x3a, 0xda, 0xbf, 0xe1, 0x08, 0x2f, 0x58, 0x38, 0xea, 0xd3, 0x07, 0xd7, - 0x19, 0x88, 0xc5, 0x32, 0xba, 0x0e, 0xe1, 0x0e, 0x4a, 0x4a, 0xbb, 0x43, 0xcb, 0xac, 0xe6, 0x11, - 0x75, 0x23, 0xb5, 0x50, 0x10, 0xce, 0x15, 0x78, 0xf5, 0x0e, 0xe9, 0xba, 0x83, 0xea, 0xfa, 0xd2, - 0x44, 0x8b, 0xed, 0xb7, 0x0a, 0xd8, 0x13, 0x7a, 0x37, 0x5d, 0x46, 0x0a, 0xc2, 0x8f, 0x19, 0xc6, - 0xe7, 0xb9, 0xb8, 0xee, 0x00, 0x9b, 0xef, 0x6c, 0xaf, 0xfd, 0x9a, 0x36, 0x6f, 0xdb, 0x61, 0x4d, - 0x5a, 0x39, 0x97, 0x2b, 0x7c, 0x4f, 0x37, 0x30, 0x47, 0xd6, 0xa2, 0xb5, 0x4f, 0x22, 0xca, 0x24, - 0x3e, 0x8b, 0x1b, 0xd8, 0xe2, 0xe5, 0xde, 0x0b, 0x32, 0x78, 0xb5, 0xd9, 0x72, 0xe7, 0x62, 0xcb, - 0x9d, 0xab, 0x2d, 0x27, 0x5f, 0x73, 0x4e, 0x7e, 0xe6, 0x9c, 0xac, 0x73, 0x4e, 0x36, 0x39, 0x27, - 0xbf, 0x73, 0x4e, 0xfe, 0xe4, 0xdc, 0xb9, 0xca, 0x39, 0xf9, 0xbe, 0xe3, 0xce, 0x66, 0xc7, 0x9d, - 0x8b, 0x1d, 0x77, 0x3e, 0xd8, 0x9f, 0x39, 0xda, 0xc7, 0x3f, 0xf2, 0xfc, 0x6f, 0x00, 0x00, 0x00, - 0xff, 0xff, 0x24, 0xfa, 0x1b, 0xec, 0xb6, 0x02, 0x00, 0x00, + // 486 bytes of a gzipped FileDescriptorProto + 0x1f, 0x8b, 0x08, 0x00, 0x00, 0x00, 0x00, 0x00, 0x02, 0xff, 0x8c, 0x92, 0x41, 0x6f, 0xd3, 0x30, + 0x14, 0xc7, 0xe3, 0xb5, 0x1d, 0x8d, 0x3b, 0xa4, 0x62, 0x8a, 0xc8, 0x2a, 0xe1, 0x15, 0xb8, 0xf4, + 0x80, 0x52, 0x54, 0x2e, 0x08, 0x24, 0x34, 0x75, 0x1b, 0xe2, 0x4a, 0x8b, 0x84, 0xb4, 0x8b, 0xe5, + 0xb6, 0x6e, 0x6a, 0x2d, 0x8d, 0x4b, 0xe2, 0x00, 0xb9, 0xf1, 0x11, 0x38, 0xf2, 0x11, 0xf8, 0x28, + 0x3d, 0xf6, 0xb8, 0xd3, 0xa0, 0xa9, 0x90, 0x38, 0xee, 0x23, 0x20, 0x3f, 0x27, 0x1b, 0xec, 0xc4, + 0xcd, 0x7e, 0xbf, 0xf7, 0x7f, 0xf2, 0xff, 0xff, 0x8c, 0x1b, 0x89, 0xe6, 0x3a, 0xf1, 0x97, 0xb1, + 0xd2, 0x8a, 0xd4, 0xe0, 0xd2, 0x6e, 0x05, 0x2a, 0x50, 0x50, 0xe9, 0x99, 0x93, 0x85, 0x6d, 0x1a, + 0x28, 0x15, 0x84, 0xa2, 0x07, 0xb7, 0x71, 0x3a, 0xeb, 0x4d, 0xd3, 0x98, 0x6b, 0xa9, 0xa2, 0x82, + 0xef, 0xdf, 0xe4, 0x3c, 0xca, 0x2c, 0x7a, 0xf4, 0xab, 0x8a, 0x6b, 0x23, 0x33, 0x9a, 0x1c, 0x62, + 0xf7, 0x13, 0x0f, 0x43, 0xa6, 0xe5, 0x42, 0x78, 0xa8, 0x83, 0xba, 0x8d, 0xfe, 0xbe, 0x6f, 0x85, + 0x7e, 0x29, 0xf4, 0x8f, 0x8b, 0xc1, 0x83, 0xfa, 0xea, 0xe2, 0xc0, 0xf9, 0xf6, 0xe3, 0x00, 0x0d, + 0xeb, 0x46, 0xf5, 0x4e, 0x2e, 0x04, 0x79, 0x8a, 0x5b, 0x33, 0xa1, 0x27, 0x73, 0x31, 0x65, 0x89, + 0x88, 0xa5, 0x48, 0xd8, 0x44, 0xa5, 0x91, 0xf6, 0x76, 0x3a, 0xa8, 0x5b, 0x1d, 0x92, 0x82, 0x8d, + 0x00, 0x1d, 0x19, 0x42, 0x7c, 0x7c, 0xb7, 0x54, 0x4c, 0xe6, 0x69, 0x74, 0xc6, 0xc6, 0x99, 0x16, + 0x89, 0x57, 0x01, 0xc1, 0x9d, 0x02, 0x1d, 0x19, 0x32, 0x30, 0x80, 0x3c, 0xc1, 0xe5, 0x14, 0x36, + 0xe5, 0x9a, 0x17, 0xed, 0x55, 0x68, 0x6f, 0x16, 0xe4, 0x98, 0x6b, 0x6e, 0xbb, 0x0f, 0xf1, 0x9e, + 0xf8, 0xac, 0x63, 0xce, 0x66, 0x52, 0x84, 0xd3, 0xc4, 0xab, 0x75, 0x2a, 0xdd, 0x46, 0xff, 0x81, + 0x6f, 0x73, 0x05, 0xd7, 0xfe, 0x89, 0x69, 0x78, 0x0d, 0xfc, 0x24, 0xd2, 0x71, 0x36, 0x6c, 0x88, + 0xeb, 0xca, 0xdf, 0x8e, 0xe0, 0x7d, 0xa5, 0xa3, 0xdd, 0x7f, 0x1c, 0xc1, 0x03, 0x0b, 0x47, 0x7d, + 0x7c, 0xef, 0x2a, 0x03, 0xbe, 0x58, 0x86, 0x57, 0x21, 0xdc, 0x02, 0x49, 0x69, 0x77, 0x64, 0x99, + 0xd5, 0x3c, 0xc4, 0x6e, 0x28, 0x17, 0x52, 0xb3, 0xb9, 0xd4, 0x5e, 0xbd, 0x83, 0xba, 0xee, 0xa0, + 0xba, 0xba, 0x30, 0xd1, 0x42, 0xf9, 0x8d, 0xd4, 0xe4, 0x31, 0xbe, 0x9d, 0x2c, 0x43, 0xa9, 0xd9, + 0x87, 0x14, 0xe2, 0xf3, 0x5c, 0x18, 0xb7, 0x07, 0xc5, 0xb7, 0xb6, 0x46, 0x4e, 0xf1, 0x7d, 0x83, + 0x33, 0x96, 0x68, 0x15, 0xf3, 0x40, 0xb0, 0xeb, 0x7d, 0xe2, 0xff, 0xdf, 0x67, 0x0b, 0x66, 0x8c, + 0xec, 0x88, 0xf7, 0xc5, 0x6e, 0xdb, 0xaf, 0x70, 0xf3, 0x66, 0x54, 0xa4, 0x89, 0x2b, 0x67, 0x22, + 0x83, 0xbf, 0xe2, 0x0e, 0xcd, 0x91, 0xb4, 0x70, 0xed, 0x23, 0x0f, 0x53, 0x01, 0x2b, 0x77, 0x87, + 0xf6, 0xf2, 0x62, 0xe7, 0x39, 0x1a, 0xbc, 0x5c, 0x6f, 0xa8, 0x73, 0xbe, 0xa1, 0xce, 0xe5, 0x86, + 0xa2, 0x2f, 0x39, 0x45, 0xdf, 0x73, 0x8a, 0x56, 0x39, 0x45, 0xeb, 0x9c, 0xa2, 0x9f, 0x39, 0x45, + 0xbf, 0x73, 0xea, 0x5c, 0xe6, 0x14, 0x7d, 0xdd, 0x52, 0x67, 0xbd, 0xa5, 0xce, 0xf9, 0x96, 0x3a, + 0xa7, 0xf6, 0xd7, 0x8f, 0x77, 0xe1, 0xbd, 0xcf, 0xfe, 0x04, 0x00, 0x00, 0xff, 0xff, 0x39, 0x10, + 0xd3, 0xa4, 0x12, 0x03, 0x00, 0x00, } func (this *Stats) Equal(that interface{}) bool { @@ -239,13 +250,16 @@ func (this *Stats) Equal(that interface{}) bool { if this.SplitQueries != that1.SplitQueries { return false } + if this.QueryStorageWallTime != that1.QueryStorageWallTime { + return false + } return true } func (this *Stats) GoString() string { if this == nil { return "nil" } - s := make([]string, 0, 13) + s := make([]string, 0, 14) s = append(s, "&stats.Stats{") s = append(s, "WallTime: "+fmt.Sprintf("%#v", this.WallTime)+",\n") s = append(s, "FetchedSeriesCount: "+fmt.Sprintf("%#v", this.FetchedSeriesCount)+",\n") @@ -268,6 +282,7 @@ func (this *Stats) GoString() string { s = append(s, "FetchedSamplesCount: "+fmt.Sprintf("%#v", this.FetchedSamplesCount)+",\n") s = append(s, "LimitHit: "+fmt.Sprintf("%#v", this.LimitHit)+",\n") s = append(s, "SplitQueries: "+fmt.Sprintf("%#v", this.SplitQueries)+",\n") + s = append(s, "QueryStorageWallTime: "+fmt.Sprintf("%#v", this.QueryStorageWallTime)+",\n") s = append(s, "}") return strings.Join(s, "") } @@ -299,6 +314,14 @@ func (m *Stats) MarshalToSizedBuffer(dAtA []byte) (int, error) { _ = i var l int _ = l + n1, err1 := github_com_gogo_protobuf_types.StdDurationMarshalTo(m.QueryStorageWallTime, dAtA[i-github_com_gogo_protobuf_types.SizeOfStdDuration(m.QueryStorageWallTime):]) + if err1 != nil { + return 0, err1 + } + i -= n1 + i = encodeVarintStats(dAtA, i, uint64(n1)) + i-- + dAtA[i] = 0x52 if m.SplitQueries != 0 { i = encodeVarintStats(dAtA, i, uint64(m.SplitQueries)) i-- @@ -355,12 +378,12 @@ func (m *Stats) MarshalToSizedBuffer(dAtA []byte) (int, error) { i-- dAtA[i] = 0x10 } - n1, err1 := github_com_gogo_protobuf_types.StdDurationMarshalTo(m.WallTime, dAtA[i-github_com_gogo_protobuf_types.SizeOfStdDuration(m.WallTime):]) - if err1 != nil { - return 0, err1 + n2, err2 := github_com_gogo_protobuf_types.StdDurationMarshalTo(m.WallTime, dAtA[i-github_com_gogo_protobuf_types.SizeOfStdDuration(m.WallTime):]) + if err2 != nil { + return 0, err2 } - i -= n1 - i = encodeVarintStats(dAtA, i, uint64(n1)) + i -= n2 + i = encodeVarintStats(dAtA, i, uint64(n2)) i-- dAtA[i] = 0xa return len(dAtA) - i, nil @@ -415,6 +438,8 @@ func (m *Stats) Size() (n int) { if m.SplitQueries != 0 { n += 1 + sovStats(uint64(m.SplitQueries)) } + l = github_com_gogo_protobuf_types.SizeOfStdDuration(m.QueryStorageWallTime) + n += 1 + l + sovStats(uint64(l)) return n } @@ -448,6 +473,7 @@ func (this *Stats) String() string { `FetchedSamplesCount:` + fmt.Sprintf("%v", this.FetchedSamplesCount) + `,`, `LimitHit:` + fmt.Sprintf("%v", this.LimitHit) + `,`, `SplitQueries:` + fmt.Sprintf("%v", this.SplitQueries) + `,`, + `QueryStorageWallTime:` + strings.Replace(strings.Replace(fmt.Sprintf("%v", this.QueryStorageWallTime), "Duration", "duration.Duration", 1), `&`, ``, 1) + `,`, `}`, }, "") return s @@ -795,6 +821,39 @@ func (m *Stats) Unmarshal(dAtA []byte) error { break } } + case 10: + if wireType != 2 { + return fmt.Errorf("proto: wrong wireType = %d for field QueryStorageWallTime", wireType) + } + var msglen int + for shift := uint(0); ; shift += 7 { + if shift >= 64 { + return ErrIntOverflowStats + } + if iNdEx >= l { + return io.ErrUnexpectedEOF + } + b := dAtA[iNdEx] + iNdEx++ + msglen |= int(b&0x7F) << shift + if b < 0x80 { + break + } + } + if msglen < 0 { + return ErrInvalidLengthStats + } + postIndex := iNdEx + msglen + if postIndex < 0 { + return ErrInvalidLengthStats + } + if postIndex > l { + return io.ErrUnexpectedEOF + } + if err := github_com_gogo_protobuf_types.StdDurationUnmarshal(&m.QueryStorageWallTime, dAtA[iNdEx:postIndex]); err != nil { + return err + } + iNdEx = postIndex default: iNdEx = preIndex skippy, err := skipStats(dAtA[iNdEx:]) diff --git a/pkg/querier/stats/stats.proto b/pkg/querier/stats/stats.proto index 96540201f0..989f71ecef 100644 --- a/pkg/querier/stats/stats.proto +++ b/pkg/querier/stats/stats.proto @@ -31,4 +31,6 @@ message Stats { // The total number of split queries sent after going through all the middlewares. // It includes the number of requests that might be discarded by the queue. uint64 split_queries = 9; + // The sum of wall time spent in the querier to fetch and merge data from storage. + google.protobuf.Duration query_storage_wall_time = 10 [(gogoproto.stdduration) = true, (gogoproto.nullable) = false]; } diff --git a/pkg/querier/stats/stats_test.go b/pkg/querier/stats/stats_test.go index d9658acc2f..54a7b80da5 100644 --- a/pkg/querier/stats/stats_test.go +++ b/pkg/querier/stats/stats_test.go @@ -133,30 +133,56 @@ func TestStats_AddFetchedSamples(t *testing.T) { }) } +func TestStats_StorageWallTime(t *testing.T) { + t.Run("add and load query storage wall time", func(t *testing.T) { + stats, _ := ContextWithEmptyStats(context.Background()) + stats.AddQueryStorageWallTime(time.Second) + stats.AddQueryStorageWallTime(time.Second) + + assert.Equal(t, 2*time.Second, stats.LoadQueryStorageWallTime()) + }) + + t.Run("add and load query storage wall time nil receiver", func(t *testing.T) { + var stats *QueryStats + stats.AddQueryStorageWallTime(time.Second) + + assert.Equal(t, time.Duration(0), stats.LoadQueryStorageWallTime()) + }) +} + func TestStats_Merge(t *testing.T) { t.Parallel() t.Run("merge two stats objects", func(t *testing.T) { stats1 := &QueryStats{} stats1.AddWallTime(time.Millisecond) + stats1.AddQueryStorageWallTime(2 * time.Second) stats1.AddFetchedSeries(50) stats1.AddFetchedChunkBytes(42) stats1.AddFetchedDataBytes(100) + stats1.AddFetchedChunks(105) + stats1.AddFetchedSamples(109) stats1.AddExtraFields("a", "b") stats1.AddExtraFields("a", "b") stats2 := &QueryStats{} stats2.AddWallTime(time.Second) + stats2.AddQueryStorageWallTime(3 * time.Second) stats2.AddFetchedSeries(60) stats2.AddFetchedChunkBytes(100) stats2.AddFetchedDataBytes(101) + stats2.AddFetchedChunks(102) + stats2.AddFetchedSamples(103) stats2.AddExtraFields("c", "d") stats1.Merge(stats2) assert.Equal(t, 1001*time.Millisecond, stats1.LoadWallTime()) + assert.Equal(t, 5*time.Second, stats1.LoadQueryStorageWallTime()) assert.Equal(t, uint64(110), stats1.LoadFetchedSeries()) assert.Equal(t, uint64(142), stats1.LoadFetchedChunkBytes()) assert.Equal(t, uint64(201), stats1.LoadFetchedDataBytes()) + assert.Equal(t, uint64(207), stats1.LoadFetchedChunks()) + assert.Equal(t, uint64(212), stats1.LoadFetchedSamples()) checkExtraFields(t, []interface{}{"a", "b", "c", "d"}, stats1.LoadExtraFields()) }) @@ -167,6 +193,7 @@ func TestStats_Merge(t *testing.T) { stats1.Merge(stats2) assert.Equal(t, time.Duration(0), stats1.LoadWallTime()) + assert.Equal(t, time.Duration(0), stats1.LoadQueryStorageWallTime()) assert.Equal(t, uint64(0), stats1.LoadFetchedSeries()) assert.Equal(t, uint64(0), stats1.LoadFetchedChunkBytes()) assert.Equal(t, uint64(0), stats1.LoadFetchedDataBytes()) diff --git a/pkg/ruler/compat.go b/pkg/ruler/compat.go index 6ae52986f5..bfc64dbb8b 100644 --- a/pkg/ruler/compat.go +++ b/pkg/ruler/compat.go @@ -245,6 +245,7 @@ func RecordAndReportRuleQueryMetrics(qf rules.QueryFunc, queryTime prometheus.Co "query", qs, "cortex_ruler_query_seconds_total", querySeconds, "query_wall_time_seconds", queryStats.WallTime, + "query_storage_wall_time_seconds", queryStats.QueryStorageWallTime, "fetched_series_count", queryStats.FetchedSeriesCount, "fetched_chunks_count", queryStats.FetchedChunksCount, "fetched_samples_count", queryStats.FetchedSamplesCount, From 9817baee4a27bcff2c7444c7a5003d6558d586b8 Mon Sep 17 00:00:00 2001 From: Ben Ye Date: Tue, 5 Mar 2024 17:05:09 -0800 Subject: [PATCH 2/2] changelog Signed-off-by: Ben Ye --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 44fe71076f..cb6919a574 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -25,6 +25,7 @@ * [ENHANCEMENT] Upgrade to go 1.21.6. #5765 * [ENHANCEMENT] AlertManager: Retrying AlertManager Delete Silence on error #5794 * [ENHANCEMENT] Ingester: Add new ingester metric `cortex_ingester_max_inflight_query_requests`. #5798 +* [ENHANCEMENT] Query: Added `query_storage_wall_time` to Query Frontend and Ruler query stats log for wall time spent on fetching data from storage. Query evaluation is not included. #5799 * [BUGFIX] Distributor: Do not use label with empty values for sharding #5717 * [BUGFIX] Query Frontend: queries with negative offset should check whether it is cacheable or not. #5719 * [BUGFIX] Redis Cache: pass `cache_size` config correctly. #5734