Huge amount of logs on the tempo querier after a single query

[ogxd]

Hello!

I am not sure if this is a bug or simply a misconfiguration issue, but we have been using Tempo for some time, and our cloud costs for it are outrageously high for the very little load we push at it (it receives less than a trace per second). The reason is difficult to pinpoint, but while looking at the tempo querier logs, I found it was spamming with info logs for every single query I do.

Let take a example:
If ask for the trace 12300000000000000000000000000000 using this GET endpoint https://tempo.mycompany.com/api/traces/12300000000000000000000000000000

And I get thousands of logs in return:

level=info ts=2024-03-26T12:39:01.007456164Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=584fece7-8609-4a73-9889-674acf7e9ea4 found=false
level=info ts=2024-03-26T12:39:01.00998329Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=6ee5f484-02ae-48e7-881c-eca80827fc40 found=false
level=info ts=2024-03-26T12:39:01.010325625Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=30b88876-dad5-4f56-a3b5-b98b239246fa found=false
level=info ts=2024-03-26T12:39:01.011833802Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=56accc55-8112-45b8-a4ee-dcbe5f884b1c found=false
level=info ts=2024-03-26T12:39:01.012966288Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=892e6987-ff02-4f38-8cc9-e3e8a92705c3 found=false
level=info ts=2024-03-26T12:39:01.015533519Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=7a20d996-c8c8-46ff-aa96-009a98fd2ea9 found=false
level=info ts=2024-03-26T12:39:01.023743664Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=d3d615e4-1aaf-42e7-a1fe-3221f299c7be found=false
level=info ts=2024-03-26T12:39:01.027216084Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=9d5ba6cd-4b0e-4cc0-93ec-976db8f0e0e9 found=false
level=info ts=2024-03-26T12:39:01.027974048Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=574e933a-234c-4dd4-afd4-0f182ff78f4e found=false
level=info ts=2024-03-26T12:39:01.03078017Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=4f862b60-7334-42b9-af27-5a95f6cfe4f3 found=false
level=info ts=2024-03-26T12:39:01.032400415Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=294cf8db-9241-4233-9049-15a69a37a2f8 found=false
level=info ts=2024-03-26T12:39:01.036625913Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=639ee226-5e79-4ac8-a364-35ed6d751c02 found=false
level=info ts=2024-03-26T12:39:01.051206716Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=9f6a1b3a-cda5-40c7-97ad-fce575332d31 found=false
level=info ts=2024-03-26T12:39:01.054659646Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=d33d1911-852a-4010-bf26-dd9366dfc6d1 found=false
level=info ts=2024-03-26T12:39:01.054861723Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=32372165-ef66-4458-8d3c-5d438d840578 found=false
level=info ts=2024-03-26T12:39:01.057402018Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=8e33c1ed-e9d5-45b8-9e5b-08c81a7d26e3 found=false
level=info ts=2024-03-26T12:39:01.057765569Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=5158bf0d-ba3a-4e66-842c-d15042bca3eb found=false
level=info ts=2024-03-26T12:39:01.057818607Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=608d830c-30db-436b-86fe-bc66e6f5bc46 found=false
level=info ts=2024-03-26T12:39:01.066375116Z caller=tempodb.go:330 org_id=single-tenant msg="searching for trace in block" findTraceID=12300000000000000000000000000000 block=66d53545-9053-475a-8617-a21b4ddf9ac9 found=false
[...]

If I get it right, the query is itself querying thousands of blocks to find 12300000000000000000000000000000? It might be the reason why egress costs are so high. Why are there so many blocks? Can this be optimized or better configured on our end?

For context: we're using tempo-distributed helm chart v1.8.5. We have been using tempo since v1.0.0. Our data is stored in GCS. Compactor is running and is configured with the helm chart default values.

Thanks in advance!

[joe-elliott]

When searching for traces by id Tempo does in fact check every block. First it checks a bloom filter, if that passes then it moves on to checking the actual block for data. That is a fairly intense log and should probably be dropped to "debug" level.

You can check tempodb_blocklist_length to determine the length of the current blocklist. There is no magic number for the perfect number of blocks. You can scale up compactors, reduce their compaction_window, or just reduce retention to help drive them down if desired.

Also, you can pass start/end parameters to that endpoint. This will force Tempo to search fewer blocks.

[ogxd]

Thanks a lot @joe-elliott for giving an explanation PLUS a bunch of solutions! Very appreciated!

Using start/end is probably the solution we were looking for. If I understand correctly the documentation, we need to pass both to avoid Tempo scanning every block (otherwise I'd have guessed that providing start only would have Tempo ignore blocks of the past up to this start epoch).

For context, we're using Tempo for end-to-end automated tests (call an API of ours with a given trace ID and some flag to bypass trace sampling, wait for a few seconds, query the trace from Tempo with the trace ID, and run a bunch of assertions on some of the trace properties). Fine-tuning the compaction_window may also help a second time.

[ogxd]

I have one additional question if I may, on the Grafana side I doubt start and end parameters are used? For instance here I search a given trace ID with a time range selected (last hour).

When inspecting the query sent I can't find the start and end being passed anywhere. There is a from and to, but both are set to "0".

When I look at the queried logs, I do see a massive amount of logs, as if it was scanning every existing block. We're using Grafana v10.3.3.

[ogxd]

It seems to originate from this https://github.com/grafana/grafana/blob/618cf8e5a103b0cf14c1ed9202b0c36b69d3564a/public/app/plugins/datasource/tempo/datasource.ts#L650

[joe-elliott]

I'm honestly sure what (if any) cases Grafana sends start/end. To prevent confusion on the main explore screen they don't send it b/c a user generally just expects Tempo to look everywhere.

Perhaps when moving from logs -> traces or metrics -> traces those params are used?