Flushes triggered by `/flush` and `/shutdown` interfere with natural `flush_check_period` flushes, causing interleaved parquet blocks and broken ingesters

[cancub]

Describe the bug

This is a 95% overlap with the problem described in Issue 2129, where the process of the problem is

1. Blocks are not being cleared from Tempo's PVC because
2. Blocks are not being flushed because
3. One of the ingester's flush queues stops processing flush operations because
4. A flush operation in the queue hangs indefinitely because

In the case of 2129, the ultimate source of the issue was

a racy deadlock in the azure-storage-blob-go SDK we use

In our case, this appears to be a problem entirely within the Tempo ingester itself whereby its creating parquet blocks that take hundreds to thousands of times longer to process than normal. This prevents flushes, which means that the blocks stick around forever when working in a kubernetes context where the ingesters are running in a StatefulSet.

We've observed a few things with this bug

1. There appears to be a correlation between an external (i.e., user or kubernetes) call to /flush or /shutdown and the creation of a bad block
2. There may also be a correlation between a large number of TRACE_TOO_LARGE errors with respect to a block and the creation of a bad block
   • this may just be a red herring though
3. No matter what precipitated these bad blocks, the result is always the same: the rows of within the parquet file are sorted-interleaved

By sorted-interleaved, I mean what we see in the following image:

As the annotations note, the block contains two sets of interleaved rows, with each sorted by their respective trace IDs.
It essentially looks like two blocks were sorted individually and then folded into one another like two decks of cards.

To Reproduce

One process that we've had good results with in reproducing this problem is to simply hit the /flush endpoint over and over, e.g.,

while true ; do curl localhost:3100/flush; done

or

while true ; do curl localhost:3100/flush; sleep 9; done

or

while true ; do curl localhost:3100/flush; sleep 29; done

Eventually some of these flushes will trigger the interleaving, and the resulting blocks take upwards of 30 minutes to process.

Expected behavior

All blocks go through the usual process of

1. completing
2. completed
3. flushing
4. flushed
5. removed

Environment:

• Infrastructure: Kubernetes, distributed Tempo
• Deployment tool: helm

Additional Context

We've got a few working theories, but our primary one is related to a potential for simultaneous flush operations

• one caused by the natural operational cycle of an instance within the ingester
• one caused by some external entity shutting down the ingester (/flush or /shutdown)

Some notes from our attempts at understanding this (note that the code references are for 2.7.1 but we're still seeing this in 2.8.2):

When a trace comes in it goes trough a bit of processing, the important part is that it eventually hits

• trace := i.getOrCreateTrace(id, tkn)
  • https://github.com/grafana/tempo/blob/v2.7.1/modules/ingester/instance.go#L218
  • trace is fetched from the (i *instance).traces[] map
• trace.Push (ctx, i.instanceID, traceBytes)
  • https://github.com/grafana/tempo/blob/v2.7.1/modules/ingester/instance.go#L220
  • Bytes are added to the traces (this is usually coming from the different spans that compose a trace)
• t.batches = append(t.batches, trace)
  • https://github.com/grafana/tempo/blob/v2.7.1/modules/ingester/trace.go#L36
  • Under traces (t *liveTrace).batches means that the spans somewhat under (i *instance).traces[].batches[].traceBytes

At this point the traces are only in memory. The path for these files to be transferred to disk is through :

• (i *instance) CutCompleteTraces(cutoff time.Duration, immediate bool)
  • https://github.com/grafana/tempo/blob/v2.7.1/modules/ingester/instance.go#L238
  • called in (i *Ingester) Fush ()
    • https://github.com/grafana/tempo/blob/v2.7.1/modules/ingester/flush.go#L82
    • this loops through all instances (related to tenant head blocks) and cut complete traces as part of a shutdown
  • Called in (i *Ingester) sweepInstance(instance *instance, immediate bool)
    • https://github.com/grafana/tempo/blob/v2.7.1/modules/ingester/flush.go#L163
    • Sweep instance is call in different situation.
      • under (i *Ingester) FlushHandler(w http.ResponseWriter, r *http.Request) triggered by the /flush endpoint
      • and by sweep all instances called by
        • by the flush handler same as above if no instances is provided by http call (flush all)
        • by the flushRemaining called by shutdown handler /shutdown
        • by (i *Ingester) stopping a slightly different but similar condition. it is received by the parent service.
        • finally the (i *Ingester) loop this is the main normal operation. I believe under normal condition and no call to /flush, there should be only one non concurrent call to the function.

In Summary we write from memory to disk in the following conditions:

1. Periodic loop, every cfg.FlushCheckPeriod (10s in our case)
2. On command, if the ingester receives a /flush http request
3. On shutdown, potentially through both /shutdown and from the parent process, from what I can tell through the context or some other channe.

[joe-elliott]

Thank you for this detailed writeup. As far as I know we are not seeing this issue, but we almost never call /flush or /shutdown so perhaps that's why. Lot of Qs!

This prevents flushes, which means that the blocks stick around forever when working in a kubernetes context where the ingesters are running in a StatefulSet.

Reviewing the code it is unfortunate that one flush goroutine maps to one queue. If a goroutine is blocked for any reason then its queue is no longer serviced. Regardless of the rest of this issue I think that this behavior is worth improving. A blocked goroutine for any reason should not prevent jobs in the queue from being dequeued.

No matter what precipitated these bad blocks, the result is always the same: the rows of within the parquet file are sorted-interleaved

This is wild. I don't think we've ever seen this, but it makes sense that these blocks are taking longer to flush. Ordered blocks are important for block completion.

Questions!

Are there any repeated IDs? Do you believe it's the same wal block completed 2x to the same file? 2 different wal blocks that have somehow been mixed together? or maybe just one wal block that somehow was incorrectly sorted when completed?

Here's a weird question. Is there anyway 2 ingesters are sharing the same disk?

An ingester logs lines like:

2025-11-15 21:09:08.564infolevel=info ts=2025-11-15T21:09:08.56471779Z caller=flush.go:283 msg="block completed" tenant=1107816 blockID=bcce7da8-ff60-4029-ad1c-c34e74330774 duration=8.530995808s
2025-11-15 21:09:08.277infolevel=info ts=2025-11-15T21:09:08.277737136Z caller=flush.go:267 msg="completing block" tenant=722195 block=67e9167b-cbc2-49d7-a942-094efba80798
2025-11-15 21:09:08.200infolevel=info ts=2025-11-15T21:09:08.200379488Z caller=flush.go:196 msg="enqueueing flush op" tenant=963705 block=901ad802-dd82-4c56-b4fd-1dd4fda4d59f
2025-11-15 21:09:08.180infolevel=info ts=2025-11-15T21:09:08.180803124Z caller=flush.go:283 msg="block completed" tenant=1058504 blockID=9624885a-554f-4074-bedb-98ffbb39a0fc duration=614.348543ms
2025-11-15 21:09:08.050infolevel=info ts=2025-11-15T21:09:08.050874106Z caller=flush.go:267 msg="completing block" tenant=1083248 block=0c0a59d7-b084-406e-aceb-6675eb972777
2025-11-15 21:09:07.915infolevel=info ts=2025-11-15T21:09:07.91538001Z caller=flush.go:196 msg="enqueueing flush op" tenant=723214 block=ced8e0ea-b5af-498f-87b6-173b0a8462b7

Can you search for log messages containing the guid of the bad block? It would be interesting to see the history and timing of the messages related to the block.

How often do you see this? How often are you calling /flush or /shutdown in normal operations?

Final Thoughts

Overall this will be difficult to prioritize as written b/c we are currently working on a new architecture for Tempo 3.0 which will no longer use this code. However, the livestore has a lot of inherited code from the ingester so we should keep an eye out for it there. I also think the behavior of exclusive queues should be improved so even when/if this happens the impact is not as bad.

[joe-elliott]

Oooh, I think you're right. If you call /flush it will call CutCompleteTraces on all instances:

https://github.com/grafana/tempo/blob/main/modules/ingester/flush.go#L182

And then there's the normal flush cycle.

Nothing prevents re-entrance into CutCompleteTraces. This function sorts the traces to flush, writes them to the head block (wal) and then flushes it. Here's the wal block AppendTrace. If this happens 2x simultaneously you would create a wal block segment with interleaved but sorted trace ids and completing it would take forever.

Something as simple as a mutex that prevents re-entrance into CutCompleteTraces might be enough to fix it? Are you able to experiment with a change like that?

[cancub]

That (the mutex) is exactly what we were thinking to do on our end.

We'll take a look into it and get back to your with the results.