From 728b76e032e1c92c2663c53ae57c2a4bc9734a7c Mon Sep 17 00:00:00 2001 From: Mengmeng Yang Date: Sun, 24 Jul 2022 22:19:35 -0700 Subject: [PATCH 1/2] add log to identify request cache hit and cache miss Signed-off-by: Mengmeng Yang --- pkg/querier/queryrange/results_cache.go | 29 ++++++++++++++++++++++--- 1 file changed, 26 insertions(+), 3 deletions(-) diff --git a/pkg/querier/queryrange/results_cache.go b/pkg/querier/queryrange/results_cache.go index b34dd386ad1..f47c82784ba 100644 --- a/pkg/querier/queryrange/results_cache.go +++ b/pkg/querier/queryrange/results_cache.go @@ -227,6 +227,7 @@ func (s resultsCache) Do(ctx context.Context, r Request) (Response, error) { } if s.shouldCache != nil && !s.shouldCache(r) { + level.Info(util_log.WithContext(ctx, s.logger)).Log("msg", "should not cache", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) return s.next.Do(ctx, r) } @@ -243,6 +244,7 @@ func (s resultsCache) Do(ctx context.Context, r Request) (Response, error) { maxCacheFreshness := validation.MaxDurationPerTenant(tenantIDs, s.limits.MaxCacheFreshness) maxCacheTime := int64(model.Now().Add(-maxCacheFreshness)) if r.GetStart() > maxCacheTime { + level.Info(util_log.WithContext(ctx, s.logger)).Log("msg", "cache miss", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) return s.next.Do(ctx, r) } @@ -368,6 +370,7 @@ func getHeaderValuesWithName(r Response, headerName string) (headerValues []stri } func (s resultsCache) handleMiss(ctx context.Context, r Request, maxCacheTime int64) (Response, []Extent, error) { + level.Info(util_log.WithContext(ctx, s.logger)).Log("msg", "handle miss", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) response, err := s.next.Do(ctx, r) if err != nil { return nil, nil, err @@ -396,6 +399,8 @@ func (s resultsCache) handleHit(ctx context.Context, r Request, extents []Extent log, ctx := spanlogger.New(ctx, "handleHit") defer log.Finish() + level.Info(util_log.WithContext(ctx, log)).Log("msg", "handle hit", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) + requests, responses, err := s.partition(r, extents) if err != nil { return nil, nil, err @@ -639,18 +644,36 @@ func (s resultsCache) put(ctx context.Context, key string, extents []Extent) { s.cache.Store(ctx, []string{cache.HashKey(key)}, [][]byte{buf}) } +func jaegerSpanID(ctx context.Context) string { + spanContext, ok := getSpanContext(ctx) + if !ok { + return "" + } + + return spanContext.SpanID().String() +} + func jaegerTraceID(ctx context.Context) string { + spanContext, ok := getSpanContext(ctx) + if !ok { + return "" + } + + return spanContext.TraceID().String() +} + +func getSpanContext(ctx context.Context) (jaeger.SpanContext, bool) { span := opentracing.SpanFromContext(ctx) if span == nil { - return "" + return jaeger.SpanContext{}, false } spanContext, ok := span.Context().(jaeger.SpanContext) if !ok { - return "" + return jaeger.SpanContext{}, false } - return spanContext.TraceID().String() + return spanContext, true } // extractStats returns the stats for a given time range From 3e770b6f0f25d68cd0e0f8bbb9c7cf7b80dd7450 Mon Sep 17 00:00:00 2001 From: Mengmeng Yang Date: Thu, 18 Aug 2022 13:13:48 -0700 Subject: [PATCH 2/2] change log level from info to debug Signed-off-by: Mengmeng Yang --- pkg/querier/queryrange/results_cache.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/pkg/querier/queryrange/results_cache.go b/pkg/querier/queryrange/results_cache.go index f47c82784ba..502e12e1dd5 100644 --- a/pkg/querier/queryrange/results_cache.go +++ b/pkg/querier/queryrange/results_cache.go @@ -227,7 +227,7 @@ func (s resultsCache) Do(ctx context.Context, r Request) (Response, error) { } if s.shouldCache != nil && !s.shouldCache(r) { - level.Info(util_log.WithContext(ctx, s.logger)).Log("msg", "should not cache", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) + level.Debug(util_log.WithContext(ctx, s.logger)).Log("msg", "should not cache", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) return s.next.Do(ctx, r) } @@ -244,7 +244,7 @@ func (s resultsCache) Do(ctx context.Context, r Request) (Response, error) { maxCacheFreshness := validation.MaxDurationPerTenant(tenantIDs, s.limits.MaxCacheFreshness) maxCacheTime := int64(model.Now().Add(-maxCacheFreshness)) if r.GetStart() > maxCacheTime { - level.Info(util_log.WithContext(ctx, s.logger)).Log("msg", "cache miss", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) + level.Debug(util_log.WithContext(ctx, s.logger)).Log("msg", "cache miss", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) return s.next.Do(ctx, r) } @@ -370,7 +370,7 @@ func getHeaderValuesWithName(r Response, headerName string) (headerValues []stri } func (s resultsCache) handleMiss(ctx context.Context, r Request, maxCacheTime int64) (Response, []Extent, error) { - level.Info(util_log.WithContext(ctx, s.logger)).Log("msg", "handle miss", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) + level.Debug(util_log.WithContext(ctx, s.logger)).Log("msg", "handle miss", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) response, err := s.next.Do(ctx, r) if err != nil { return nil, nil, err @@ -399,7 +399,7 @@ func (s resultsCache) handleHit(ctx context.Context, r Request, extents []Extent log, ctx := spanlogger.New(ctx, "handleHit") defer log.Finish() - level.Info(util_log.WithContext(ctx, log)).Log("msg", "handle hit", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) + level.Debug(util_log.WithContext(ctx, log)).Log("msg", "handle hit", "start", r.GetStart(), "spanID", jaegerSpanID(ctx)) requests, responses, err := s.partition(r, extents) if err != nil {