How to performance tune TraceQL tags values autocomplete?

[kostya9]

I am playing around with TraceQL, and it is really cool when the autocomplete is snappy, but a little frustrating when queries for tag values are 10+ seconds or even time out. Trace search, on the other hand, performs OK.

Are there any ways to make tag value search snappier, maybe some metrics to look at or configs to fine tune (besides just adding CPU and memory to the pod - I see that not all CPU and memory is used)?

[scalalang2]

How does Tempo do this now?
I assumes that It requires full search on all parquet files within time range right?

[kostya9]

I have little knowledge of how it does it right now, whether it reads all parquet files or maintains an index of the tags somewhere. This knowledge would help with understanding what is slow, that's for sure.

From the speed of search I see, it seems that the full search algorithm is the most likely. AFAIK that folks at Grafana use it too, so there may be some way to scale this even in this case.

[joe-elliott]

Yes, currently we scan the full parquet file to answer this question. We have generally seen fine performance with this approach but have definitely stumbled on edge cases which are quite slow. We are working to improve this.

[joe-elliott]

are your tag searches returning lots of values? you can limit the number of values by adjusting the following. it defaults to 5MB which is quite large.

overrides:
  max_bytes_per_tag_values_query: 

i'm also going to cc @mapno who is working on improving tag search and is currently investigating some performance issues we have seen.

[kostya9]

I found this endpoint - /debug/pprof/goroutine?debug=1, and found that the tags value query is sitting on a lock when it performs poorly.

2 @ 0x43ccf6 0x44dc5e 0x44dc35 0x46a425 0x1c23719 0x1c2371a 0x1c17b89 0xe68e18 0x1c4de03 0xdb59ba 0xd81f82 0xdb59ba 0xdb6ca2 0xdb59ba 0xd8231b 0xdb59ba 0xdb585e 0xe68cd8 0xa08f8b 0xa0da6f 0xa06c18 0x46e621
#	0x46a424	sync.runtime_SemacquireMutex+0x24							/usr/local/go/src/runtime/sema.go:77
#	0x1c23718	sync.(*RWMutex).RLock+0x2d8								/usr/local/go/src/sync/rwmutex.go:71
#	0x1c23719	github.com/grafana/tempo/modules/ingester.(*instance).SearchTagValues+0x2d9		/drone/src/modules/ingester/instance_search.go:431
#	0x1c17b88	github.com/grafana/tempo/modules/ingester.(*Ingester).SearchTagValues+0xa8		/drone/src/modules/ingester/ingester_search.go:59
#	0xe68e17	github.com/grafana/tempo/pkg/tempopb._Querier_SearchTagValues_Handler.func1+0x77	/drone/src/pkg/tempopb/tempo.pb.go:1794
#	0x1c4de02	github.com/grafana/tempo/cmd/tempo/app.glob..func2+0x82					/drone/src/cmd/tempo/app/fake_auth.go:22
#	0xdb59b9	github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1+0x39		/drone/src/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:25
#	0xd81f81	github.com/weaveworks/common/middleware.UnaryServerInstrumentInterceptor.func1+0xa1	/drone/src/vendor/github.com/weaveworks/common/middleware/grpc_instrumentation.go:35
#	0xdb59b9	github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1+0x39		/drone/src/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:25
#	0xdb6ca1	github.com/opentracing-contrib/go-grpc.OpenTracingServerInterceptor.func1+0x401		/drone/src/vendor/github.com/opentracing-contrib/go-grpc/server.go:57
#	0xdb59b9	github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1+0x39		/drone/src/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:25
#	0xd8231a	github.com/weaveworks/common/middleware.GRPCServerLog.UnaryServerInterceptor+0xba	/drone/src/vendor/github.com/weaveworks/common/middleware/grpc_logging.go:30
#	0xdb59b9	github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1+0x39		/drone/src/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:25
#	0xdb585d	github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1+0xbd		/drone/src/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:34
#	0xe68cd7	github.com/grafana/tempo/pkg/tempopb._Querier_SearchTagValues_Handler+0x137		/drone/src/pkg/tempopb/tempo.pb.go:1796
#	0xa08f8a	google.golang.org/grpc.(*Server).processUnaryRPC+0xb2a					/drone/src/vendor/google.golang.org/grpc/server.go:1301
#	0xa0da6e	google.golang.org/grpc.(*Server).handleStream+0xa2e					/drone/src/vendor/google.golang.org/grpc/server.go:1642
#	0xa06c17	google.golang.org/grpc.(*Server).serveStreams.func1.2+0x97				/drone/src/vendor/google.golang.org/grpc/server.go:938

From this, I see that maybe the reason could be not actual search perf, but just lock contention? Maybe some write operation is performed too frequently that takes the lock?

[mapno]

I've been taking a look at this mainly today and already found a couple of things that are making tag search slow:

• We're not exiting early when reaching overrides.max_bytes_per_tag_values_query in certain endpoints (PR)—although this shouldn't be affecting TraceQL.
• Some special tags such as status.code are being search for exhaustively, when we could return immediately (there only three values it can take, due to semantic conventions).
• Next thing I'm taking a look at is lock contention. We found several traces where lock contention was evident. The profile you share here is a great lead. I'm looking to run Tempo with runtime.SetBlockProfileRate and more profile information to figure out what's causing the contention (ie. WAL block, flushed blocks to disk, etc).

I'll update the discussion as we find more things. All the feedback is very helpful, thanks.

[kostya9]

After getting a little bit more familiar with the code, I am thinking... Maybe the issue I found (failed ingester completing) in #2034 (comment) may be impacting the perf?

Looks like all of the space used is in WAL

Does failed completing mean that the tag values search will attempt to read all of the data that is collected - hundred of gigs? Which may increase lock contention and degrade the perf even more?

My line of thinking - If we don't clear completing block, then we don't flush, then we don't move the data from wal to longer-term storage. We also don't remove the block from completeBlocks, which causes it to be searched by tag values search

[joe-elliott]

Yeah. I agree that if your completed blocks are not being flushed then that is likely the cause of your very long tag search times. Perhaps we should focus on where these .nfs files are coming from and how we can make Tempo "play nice" with them.

[kostya9]

Thanks for the assistance!