diff --git a/pkg/storage/stores/shipper/bloomshipper/client.go b/pkg/storage/stores/shipper/bloomshipper/client.go index 1c2314691cae..56e81a4d3fe4 100644 --- a/pkg/storage/stores/shipper/bloomshipper/client.go +++ b/pkg/storage/stores/shipper/bloomshipper/client.go @@ -23,6 +23,7 @@ import ( "github.com/grafana/loki/v3/pkg/storage/config" "github.com/grafana/loki/v3/pkg/storage/stores/shipper/indexshipper/tsdb" "github.com/grafana/loki/v3/pkg/util/encoding" + "github.com/grafana/loki/v3/pkg/util/spanlogger" ) const ( @@ -480,12 +481,25 @@ func newCachedListOpObjectClient(oc client.ObjectClient, ttl, interval time.Dura } func (c *cachedListOpObjectClient) List(ctx context.Context, prefix string, delimiter string) ([]client.StorageObject, []client.StorageCommonPrefix, error) { + var ( + logger = spanlogger.FromContext(ctx) + start = time.Now() + cacheDur time.Duration + ) + defer func() { + logger.LogKV( + "cache_duration", cacheDur, + "total_duration", time.Since(start), + ) + }() + if delimiter != "" { return nil, nil, fmt.Errorf("does not support LIST calls with delimiter: %s", delimiter) } c.mtx.RLock() cached, found := c.cache[prefix] c.mtx.RUnlock() + cacheDur = time.Since(start) if found { return cached.objects, cached.prefixes, nil } diff --git a/pkg/storage/stores/shipper/bloomshipper/fetcher.go b/pkg/storage/stores/shipper/bloomshipper/fetcher.go index de02d1effba8..69715158950e 100644 --- a/pkg/storage/stores/shipper/bloomshipper/fetcher.go +++ b/pkg/storage/stores/shipper/bloomshipper/fetcher.go @@ -19,6 +19,7 @@ import ( v1 "github.com/grafana/loki/v3/pkg/storage/bloom/v1" "github.com/grafana/loki/v3/pkg/storage/chunk/cache" "github.com/grafana/loki/v3/pkg/util/constants" + "github.com/grafana/loki/v3/pkg/util/spanlogger" ) var downloadQueueCapacity = 10000 @@ -119,6 +120,8 @@ func (f *Fetcher) Close() { // FetchMetas implements fetcher func (f *Fetcher) FetchMetas(ctx context.Context, refs []MetaRef) ([]Meta, error) { + logger := spanlogger.FromContextWithFallback(ctx, f.logger) + if ctx.Err() != nil { return nil, errors.Wrap(ctx.Err(), "fetch Metas") } @@ -127,9 +130,12 @@ func (f *Fetcher) FetchMetas(ctx context.Context, refs []MetaRef) ([]Meta, error for _, ref := range refs { keys = append(keys, f.client.Meta(ref).Addr()) } + + cacheStart := time.Now() cacheHits, cacheBufs, _, err := f.metasCache.Fetch(ctx, keys) + cacheDur := time.Since(cacheStart) if err != nil { - level.Error(f.logger).Log("msg", "failed to fetch metas from cache", "err", err) + level.Error(logger).Log("msg", "failed to fetch metas from cache", "err", err) return nil, nil } @@ -138,16 +144,31 @@ func (f *Fetcher) FetchMetas(ctx context.Context, refs []MetaRef) ([]Meta, error return nil, err } + storageStart := time.Now() fromStorage, err := f.client.GetMetas(ctx, missing) + storageDur := time.Since(storageStart) if err != nil { return nil, err } + writeBackStart := time.Now() err = f.writeBackMetas(ctx, fromStorage) + writeBackDur := time.Since(writeBackStart) if err != nil { return nil, err } + logger.LogKV( + "phase", "fetch_metas", + "err", err, + "keys", len(keys), + "hits", len(cacheHits), + "misses", len(missing), + "cache_dur", cacheDur.String(), + "storage_dur", storageDur.String(), + "write_back_dur", writeBackDur.String(), + ) + results := append(fromCache, fromStorage...) f.metrics.metasFetched.Observe(float64(len(results))) // TODO(chaudum): get metas size from storage diff --git a/pkg/storage/stores/shipper/bloomshipper/store.go b/pkg/storage/stores/shipper/bloomshipper/store.go index 5e1363d0cb73..9b18427bacf1 100644 --- a/pkg/storage/stores/shipper/bloomshipper/store.go +++ b/pkg/storage/stores/shipper/bloomshipper/store.go @@ -21,6 +21,7 @@ import ( "github.com/grafana/loki/v3/pkg/storage/chunk/client/util" "github.com/grafana/loki/v3/pkg/storage/config" "github.com/grafana/loki/v3/pkg/util/constants" + "github.com/grafana/loki/v3/pkg/util/spanlogger" ) var ( @@ -114,7 +115,11 @@ func (b *bloomStoreEntry) ResolveMetas(ctx context.Context, params MetaSearchPar // FetchMetas implements store. func (b *bloomStoreEntry) FetchMetas(ctx context.Context, params MetaSearchParams) ([]Meta, error) { + logger := spanlogger.FromContext(ctx) + + resolverStart := time.Now() metaRefs, fetchers, err := b.ResolveMetas(ctx, params) + resolverDuration := time.Since(resolverStart) if err != nil { return nil, err } @@ -122,6 +127,16 @@ func (b *bloomStoreEntry) FetchMetas(ctx context.Context, params MetaSearchParam return nil, errors.New("metaRefs and fetchers have unequal length") } + var metaCt int + for i := range metaRefs { + metaCt += len(metaRefs[i]) + } + logger.LogKV( + "msg", "resolved metas", + "metas", metaCt, + "duration", resolverDuration, + ) + var metas []Meta for i := range fetchers { res, err := fetchers[i].FetchMetas(ctx, metaRefs[i])