Logging lots of out-of-order data using the same timepoint on a timeline leads to extreme slowdown in datastore

[emilk]

A user shared a puffin profile of very slow data ingestion

slow_ingestion.puffin.zip

What I see is this: the data ingestion (which is currently happening in the main rendering loop, see #4298) gets a message containing ~3800 rows of data. Processing that takes ~2 seconds, because each insertion takes a whopping ~9ms. The bulk of the insertion cost is re-sorting, which makes me suspect that the reason for this new slowdown is out-of-order insertions.

There are several layers of bad here:

• As mentioned, we shouldn't be doing insertions on the main render loop (Parallelize data ingestion #4298)
• If we do, we should make sure to not use more than a certain time budget
• Each insertion should not be this slow, even with out-of-order insertion

Workarounds

• Run the logging with RERUN_FLUSH_NUM_ROWS=1: this will create smaller chunks of work for the viewer, which should get back the viewer frame-rate, but still with slow ingestion

• Stop logging data out-of-order. This could happen if you are using custom timelines that are not monotonically increasing. Rerun should support out-of-order logging, but it seems like we're hitting a bad corner case here.

Other notes

It would be great if we could tell from a puffin profile whether or not the code that was running was a debug or release build.
If this was from a debug build, then this whole issue is a mistake.

• EDIT: Log text via puffin EmbarkStudios/puffin#171

[teh-cmc]

The first thing that immediately jumps out to me is: why are the sorting routines even running at all on the ingestion path?!

There is only one very specific case where we ever try to sort during ingestion: the bucket is full and has to be split.
Since I don't see any trace of IndexedBucket::split in this flamegraph, it means we're early exiting before the actual split, which means the bucket only contains a single timestamp.

rerun/crates/re_arrow_store/src/store_write.rs

Lines 546 to 577 in 52ce18d

	fn split(&self) -> Option<(TimeInt, Self)> {
	let Self {
	timeline,
	cluster_key: _,
	inner,
	} = self;
	let mut inner1 = inner.write();
	inner1.sort();
	let IndexedBucketInner {
	is_sorted: _,
	time_range: time_range1,
	col_time: col_time1,
	col_insert_id: col_insert_id1,
	col_row_id: col_row_id1,
	col_num_instances: col_num_instances1,
	columns: columns1,
	size_bytes: _, // NOTE: recomputed below
	} = &mut *inner1;
	if col_time1.len() < 2 {
	return None; // early exit: can't split the unsplittable
	}
	if col_time1.first() == col_time1.last() {
	// The entire bucket contains only one timepoint, thus it's impossible to find
	// a split index to begin with.
	return None;
	}
	re_tracing::profile_function!();

But then why is the bucket sorted flag invalidated every frame?

This code looks correct:

rerun/crates/re_arrow_store/src/store_write.rs

Line 451 in 52ce18d

*is_sorted &= (*last_time, *last_row_id) <= (time.as_i64(), row.row_id());

So the only explanation I can think of is that the user is somehow repeatedly ingesting data at a single timestamp and doing so with out-of-order RowIds (maybe multiple processes and/or threads are involved)?

In any case I can probably make a patch to move that sort after the early exit: the bucket's time-range bounds are up-to-date even when the bucket is unsorted.

[teh-cmc]

It would be great if we could tell from a puffin profile whether or not the code that was running was a debug or release build.
If this was from a debug build, then this whole issue is a mistake.

+1 -- even the whole rerun versioning string ideally

[emilk]

#4417 only pushed the problem to later:

The user was using rec.set_time_sequence temporarily for logging a few things, then never called disable_timeline. The user then went on to log 800k+ of other things, all ending up on the same timepoint in this "temporary" timeline.

EDIT: I have been shared a reproduce on a private repository. It logs everything on the main thread, yet the RowId:s are reaching the batcher out-of-order for some unknown reason.

EDIT2: The cause was this: #4658

[emilk]

We do log a warning:

[2023-12-05T13:00:56Z WARN re_arrow_store::store_write] Found over 512 rows with the same timepoint "keyframes"=#35 - perhaps you forgot to update or remove the timeline "keyframes"?

I think the only solution is to actually split these buckets so they don't grow.

[emilk]

Summary: When this issue was open, we hit this extreme slow-down every time we logged a lot of data using the same time point. Since then two PRs have landed:

• Datastore: don't eagerly sort in bucket split rountine on ingestion path #4417
• Fix wrong RowId order of logged data #4658

The first reduces the sorting to only be done at query time.
This still makes the viewer really slow, but it can ingest a lot more between each slow frame,
perhaps reaching the end of the recording (if any) fast enough.

The second PR ensures we only hit the corner case if data is logged out-of-order.
It means the log rows arrive to the batcher in a different order than they were produced (swapped RowIds).
This mean there has to be a race: two threads logging to the same timeline, using the same time point.

In other words, the risk for this bug to produce extreme slowdowns is a lot smaller now.
It can still happen, but I think it is safe to lower its priority until we get more reports of it.

[emilk]

For future adventurers:

The problem with splitting the buckets further even when they share the same timepoint, is the definition of IndexTable::buckets:

pub buckets: BTreeMap<TimeInt, IndexedBucket>

Since BTreeMap doesn't allow duplicate keys, we would need to change the key there, or add "sub-buckets" inside IndexedBucket split on RowId. In either case, it is an annoying change.