Add cache usage statistics (grafana#6317)

* Adding cache statistics Signed-off-by: Danny Kopping <danny.kopping@grafana.com> * Adding metrics to metrics.go Signed-off-by: Danny Kopping <danny.kopping@grafana.com> * Creating new stats context for use in metric queries middleware Signed-off-by: Danny Kopping <danny.kopping@grafana.com> * Clean up unnecessary log fields Signed-off-by: Danny Kopping <danny.kopping@grafana.com> * Fixing tests Signed-off-by: Danny Kopping <danny.kopping@grafana.com> * Adding stats tests Signed-off-by: Danny Kopping <danny.kopping@grafana.com> * CHANGELOG entry Signed-off-by: Danny Kopping <danny.kopping@grafana.com> * Appeasing the linter Documenting function Signed-off-by: Danny Kopping <danny.kopping@grafana.com> * Moving CHANGELOG entry to appropriate section Signed-off-by: Danny Kopping <danny.kopping@grafana.com> * Implementing a stats collector cache wrapper to simplify stats collection If we keep the stats collection in pkg/storage/chunk/cache/instrumented.go, then any implementation that wraps it will cause the stats collected to be incomplete. For example: NewBackground(cacheName, cfg.Background, Instrument(cacheName, cache, reg), reg)) - the background cache requests are not collected Signed-off-by: Danny Kopping <danny.kopping@grafana.com> * Fixing tests Signed-off-by: Danny Kopping <danny.kopping@grafana.com>
dannykopping · Jun 7, 2022 · 36e0979 · 36e0979
1 parent 65e3148
commit 36e0979
Show file tree

Hide file tree

Showing 33 changed files with 1,462 additions and 123 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -74,6 +74,7 @@
 #### Loki
 
 ##### Enhancements
+* [6317](https://github.com/grafana/loki/pull/6317/files) **dannykoping**: General: add cache usage statistics
 
 ##### Fixes
 * [6152](https://github.com/grafana/loki/pull/6152) **slim-bean**: Fixes unbounded ingester memory growth when live tailing under specific circumstances.

diff --git a/pkg/logql/metrics.go b/pkg/logql/metrics.go
@@ -126,6 +126,14 @@ func RecordRangeAndInstantQueryMetrics(
 		"total_entries", stats.Summary.TotalEntriesReturned,
 		"queue_time", logql_stats.ConvertSecondsToNanoseconds(stats.Summary.QueueTime),
 		"subqueries", stats.Summary.Subqueries,
+		"cache_chunk_req", stats.Caches.Chunk.EntriesRequested,
+		"cache_chunk_hit", stats.Caches.Chunk.EntriesFound,
+		"cache_chunk_bytes_stored", stats.Caches.Chunk.BytesSent,
+		"cache_chunk_bytes_fetched", stats.Caches.Chunk.BytesReceived,
+		"cache_index_req", stats.Caches.Index.EntriesRequested,
+		"cache_index_hit", stats.Caches.Index.EntriesFound,
+		"cache_result_req", stats.Caches.Result.EntriesRequested,
+		"cache_result_hit", stats.Caches.Result.EntriesFound,
 	}...)
 
 	logValues = append(logValues, tagsToKeyValues(queryTags)...)

diff --git a/pkg/logql/metrics_test.go b/pkg/logql/metrics_test.go
@@ -84,7 +84,7 @@ func TestLogSlowQuery(t *testing.T) {
 	}, logqlmodel.Streams{logproto.Stream{Entries: make([]logproto.Entry, 10)}})
 	require.Equal(t,
 		fmt.Sprintf(
-			"level=info org_id=foo traceID=%s latency=slow query=\"{foo=\\\"bar\\\"} |= \\\"buzz\\\"\" query_type=filter range_type=range length=1h0m0s step=1m0s duration=25.25s status=200 limit=1000 returned_lines=10 throughput=100kB total_bytes=100kB total_entries=10 queue_time=2ns subqueries=0 source=logvolhist feature=beta\n",
+			"level=info org_id=foo traceID=%s latency=slow query=\"{foo=\\\"bar\\\"} |= \\\"buzz\\\"\" query_type=filter range_type=range length=1h0m0s step=1m0s duration=25.25s status=200 limit=1000 returned_lines=10 throughput=100kB total_bytes=100kB total_entries=10 queue_time=2ns subqueries=0 cache_chunk_req=0 cache_chunk_hit=0 cache_chunk_bytes_stored=0 cache_chunk_bytes_fetched=0 cache_index_req=0 cache_index_hit=0 cache_result_req=0 cache_result_hit=0 source=logvolhist feature=beta\n",
 			sp.Context().(jaeger.SpanContext).SpanID().String(),
 		),
 		buf.String())

diff --git a/pkg/logqlmodel/stats/context.go b/pkg/logqlmodel/stats/context.go
@@ -43,6 +43,7 @@ const (
 type Context struct {
 	querier  Querier
 	ingester Ingester
+	caches   Caches
 
 	// store is the store statistics collected across the query path
 	store Store
@@ -52,6 +53,15 @@ type Context struct {
 	mtx sync.Mutex
 }
 
+type CacheType string
+
+const (
+	ChunkCache       CacheType = "chunk" //nolint:staticcheck
+	IndexCache                 = "index"
+	ResultCache                = "result"
+	WriteDedupeCache           = "write-dedupe"
+)
+
 // NewContext creates a new statistics context
 func NewContext(ctx context.Context) (*Context, context.Context) {
 	contextData := &Context{}
@@ -79,6 +89,15 @@ func (c *Context) Ingester() Ingester {
 	}
 }
 
+// Caches returns the cache statistics accumulated so far.
+func (c *Context) Caches() Caches {
+	return Caches{
+		Chunk:  c.caches.Chunk,
+		Index:  c.caches.Index,
+		Result: c.caches.Result,
+	}
+}
+
 // Reset clears the statistics.
 func (c *Context) Reset() {
 	c.mtx.Lock()
@@ -88,6 +107,7 @@ func (c *Context) Reset() {
 	c.querier.Reset()
 	c.ingester.Reset()
 	c.result.Reset()
+	c.caches.Reset()
 }
 
 // Result calculates the summary based on store and ingester data.
@@ -99,6 +119,7 @@ func (c *Context) Result(execTime time.Duration, queueTime time.Duration, totalE
 			Store: c.store,
 		},
 		Ingester: c.ingester,
+		Caches:   c.caches,
 	})
 
 	r.ComputeSummary(execTime, queueTime, totalEntriesReturned)
@@ -168,12 +189,28 @@ func (i *Ingester) Merge(m Ingester) {
 	i.TotalReached += m.TotalReached
 }
 
+func (c *Caches) Merge(m Caches) {
+	c.Chunk.Merge(m.Chunk)
+	c.Index.Merge(m.Index)
+	c.Result.Merge(m.Result)
+}
+
+func (c *Cache) Merge(m Cache) {
+	c.EntriesFound += m.EntriesFound
+	c.EntriesRequested += m.EntriesRequested
+	c.EntriesStored += m.EntriesStored
+	c.Requests += m.Requests
+	c.BytesSent += m.BytesSent
+	c.BytesReceived += m.BytesReceived
+}
+
 // Merge merges two results of statistics.
 // This will increase the total number of Subqueries.
 func (r *Result) Merge(m Result) {
 	r.Summary.Subqueries++
 	r.Querier.Merge(m.Querier)
 	r.Ingester.Merge(m.Ingester)
+	r.Caches.Merge(m.Caches)
 	r.ComputeSummary(ConvertSecondsToNanoseconds(r.Summary.ExecTime+m.Summary.ExecTime),
 		ConvertSecondsToNanoseconds(r.Summary.QueueTime+m.Summary.QueueTime), int(r.Summary.TotalEntriesReturned))
 }
@@ -257,6 +294,85 @@ func (c *Context) AddChunksRef(i int64) {
 	atomic.AddInt64(&c.store.TotalChunksRef, i)
 }
 
+// AddCacheEntriesFound counts the number of cache entries requested and found
+func (c *Context) AddCacheEntriesFound(t CacheType, i int) {
+	stats := c.getCacheStatsByType(t)
+	if stats == nil {
+		return
+	}
+
+	atomic.AddInt32(&stats.EntriesFound, int32(i))
+}
+
+// AddCacheEntriesRequested counts the number of keys requested from the cache
+func (c *Context) AddCacheEntriesRequested(t CacheType, i int) {
+	stats := c.getCacheStatsByType(t)
+	if stats == nil {
+		return
+	}
+
+	atomic.AddInt32(&stats.EntriesRequested, int32(i))
+}
+
+// AddCacheEntriesStored counts the number of keys *attempted* to be stored in the cache
+// It should be noted that if a background writeback (https://grafana.com/docs/loki/latest/configuration/#cache_config)
+// is configured we cannot know if these store attempts succeeded or not as this happens asynchronously
+func (c *Context) AddCacheEntriesStored(t CacheType, i int) {
+	stats := c.getCacheStatsByType(t)
+	if stats == nil {
+		return
+	}
+
+	atomic.AddInt32(&stats.EntriesStored, int32(i))
+}
+
+// AddCacheBytesRetrieved counts the amount of bytes retrieved from the cache
+func (c *Context) AddCacheBytesRetrieved(t CacheType, i int) {
+	stats := c.getCacheStatsByType(t)
+	if stats == nil {
+		return
+	}
+
+	atomic.AddInt64(&stats.BytesReceived, int64(i))
+}
+
+// AddCacheBytesSent counts the amount of bytes sent to the cache
+// It should be noted that if a background writeback (https://grafana.com/docs/loki/latest/configuration/#cache_config)
+// is configured we cannot know if these bytes actually got stored or not as this happens asynchronously
+func (c *Context) AddCacheBytesSent(t CacheType, i int) {
+	stats := c.getCacheStatsByType(t)
+	if stats == nil {
+		return
+	}
+
+	atomic.AddInt64(&stats.BytesSent, int64(i))
+}
+
+// AddCacheRequest counts the number of fetch/store requests to the cache
+func (c *Context) AddCacheRequest(t CacheType, i int) {
+	stats := c.getCacheStatsByType(t)
+	if stats == nil {
+		return
+	}
+
+	atomic.AddInt32(&stats.Requests, int32(i))
+}
+
+func (c *Context) getCacheStatsByType(t CacheType) *Cache {
+	var stats *Cache
+	switch t {
+	case ChunkCache:
+		stats = &c.caches.Chunk
+	case IndexCache:
+		stats = &c.caches.Index
+	case ResultCache:
+		stats = &c.caches.Result
+	default:
+		return nil
+	}
+	return stats
+}
+
 // Log logs a query statistics result.
 func (r Result) Log(log log.Logger) {
 	_ = log.Log(
@@ -284,6 +400,7 @@ func (r Result) Log(log log.Logger) {
 		"Querier.CompressedBytes", humanize.Bytes(uint64(r.Querier.Store.Chunk.CompressedBytes)),
 		"Querier.TotalDuplicates", r.Querier.Store.Chunk.TotalDuplicates,
 	)
+	r.Caches.Log(log)
 	r.Summary.Log(log)
 }
 
@@ -297,3 +414,26 @@ func (s Summary) Log(log log.Logger) {
 		"Summary.QueueTime", ConvertSecondsToNanoseconds(s.QueueTime),
 	)
 }
+
+func (c Caches) Log(log log.Logger) {
+	_ = log.Log(
+		"Cache.Chunk.Requests", c.Chunk.Requests,
+		"Cache.Chunk.EntriesRequested", c.Chunk.EntriesRequested,
+		"Cache.Chunk.EntriesFound", c.Chunk.EntriesFound,
+		"Cache.Chunk.EntriesStored", c.Chunk.EntriesStored,
+		"Cache.Chunk.BytesSent", humanize.Bytes(uint64(c.Chunk.BytesSent)),
+		"Cache.Chunk.BytesReceived", humanize.Bytes(uint64(c.Chunk.BytesReceived)),
+		"Cache.Index.Requests", c.Index.Requests,
+		"Cache.Index.EntriesRequested", c.Index.EntriesRequested,
+		"Cache.Index.EntriesFound", c.Index.EntriesFound,
+		"Cache.Index.EntriesStored", c.Index.EntriesStored,
+		"Cache.Index.BytesSent", humanize.Bytes(uint64(c.Index.BytesSent)),
+		"Cache.Index.BytesReceived", humanize.Bytes(uint64(c.Index.BytesReceived)),
+		"Cache.Result.Requests", c.Result.Requests,
+		"Cache.Result.EntriesRequested", c.Result.EntriesRequested,
+		"Cache.Result.EntriesFound", c.Result.EntriesFound,
+		"Cache.Result.EntriesStored", c.Result.EntriesStored,
+		"Cache.Result.BytesSent", humanize.Bytes(uint64(c.Result.BytesSent)),
+		"Cache.Result.BytesReceived", humanize.Bytes(uint64(c.Result.BytesReceived)),
+	)
+}
diff --git a/pkg/logqlmodel/stats/context_test.go b/pkg/logqlmodel/stats/context_test.go
@@ -22,6 +22,9 @@ func TestResult(t *testing.T) {
 	stats.AddChunksRef(50)
 	stats.AddChunksDownloaded(60)
 	stats.AddChunksDownloadTime(time.Second)
+	stats.AddCacheRequest(ChunkCache, 3)
+	stats.AddCacheRequest(IndexCache, 4)
+	stats.AddCacheRequest(ResultCache, 1)
 
 	fakeIngesterQuery(ctx)
 	fakeIngesterQuery(ctx)
@@ -60,6 +63,17 @@ func TestResult(t *testing.T) {
 				},
 			},
 		},
+		Caches: Caches{
+			Chunk: Cache{
+				Requests: 3,
+			},
+			Index: Cache{
+				Requests: 4,
+			},
+			Result: Cache{
+				Requests: 1,
+			},
+		},
 		Summary: Summary{
 			ExecTime:                2 * time.Second.Seconds(),
 			QueueTime:               2 * time.Nanosecond.Seconds(),
@@ -182,6 +196,20 @@ func TestResult_Merge(t *testing.T) {
 				},
 			},
 		},
+		Caches: Caches{
+			Chunk: Cache{
+				Requests:      5,
+				BytesReceived: 1024,
+				BytesSent:     512,
+			},
+			Index: Cache{
+				EntriesRequested: 22,
+				EntriesFound:     2,
+			},
+			Result: Cache{
+				EntriesStored: 3,
+			},
+		},
 		Summary: Summary{
 			ExecTime:                2 * time.Second.Seconds(),
 			QueueTime:               2 * time.Nanosecond.Seconds(),
@@ -230,6 +258,20 @@ func TestResult_Merge(t *testing.T) {
 				},
 			},
 		},
+		Caches: Caches{
+			Chunk: Cache{
+				Requests:      2 * 5,
+				BytesReceived: 2 * 1024,
+				BytesSent:     2 * 512,
+			},
+			Index: Cache{
+				EntriesRequested: 2 * 22,
+				EntriesFound:     2 * 2,
+			},
+			Result: Cache{
+				EntriesStored: 2 * 3,
+			},
+		},
 		Summary: Summary{
 			ExecTime:                2 * 2 * time.Second.Seconds(),
 			QueueTime:               2 * 2 * time.Nanosecond.Seconds(),
@@ -273,3 +315,29 @@ func TestIngester(t *testing.T) {
 		},
 	}, statsCtx.Ingester())
 }
+
+func TestCaches(t *testing.T) {
+	statsCtx, _ := NewContext(context.Background())
+
+	statsCtx.AddCacheRequest(ChunkCache, 5)
+	statsCtx.AddCacheEntriesStored(ResultCache, 3)
+	statsCtx.AddCacheEntriesRequested(IndexCache, 22)
+	statsCtx.AddCacheBytesRetrieved(ChunkCache, 1024)
+	statsCtx.AddCacheBytesSent(ChunkCache, 512)
+	statsCtx.AddCacheEntriesFound(IndexCache, 2)
+
+	require.Equal(t, Caches{
+		Chunk: Cache{
+			Requests:      5,
+			BytesReceived: 1024,
+			BytesSent:     512,
+		},
+		Index: Cache{
+			EntriesRequested: 22,
+			EntriesFound:     2,
+		},
+		Result: Cache{
+			EntriesStored: 3,
+		},
+	}, statsCtx.Caches())
+}