Add detailed view of latency

[emilk]

Related

• Investigates Optimize arrow IPC encoding #9812
• Closes Investigate e2e performance of rr.log(…, rr.Image(numpy)) #9973

What

This adds a breakdown of where the end-to-end latency is coming from. It automatically appears in the top panel when latency is high. Hover it to see details:

Notable changes

The latency metrics are no longer opt-in. We always show them now if they get surprisingly high.

The measurements are made by adding extra metadata to the record batches at IPC encode/decode time.

We already have accurate timestamps at log-time (RowId) and batch-time (ChunkId).

Testing

Apply this diff:

diff --git a/tests/rust/log_benchmark/src/image.rs b/tests/rust/log_benchmark/src/image.rs
index e36478262a1..877c3e0bce4 100644
--- a/tests/rust/log_benchmark/src/image.rs
+++ b/tests/rust/log_benchmark/src/image.rs
@@ -26,8 +26,7 @@ fn prepare() -> Vec<u8> {
 fn execute(mut raw_image_data: Vec<u8>) -> anyhow::Result<()> {
     re_tracing::profile_function!();
 
-    let (rec, _storage) =
-        rerun::RecordingStreamBuilder::new("rerun_example_benchmark_").memory()?;
+    let rec = rerun::RecordingStreamBuilder::new("rerun_example_benchmark_").connect_grpc()?;
 
     for i in 0..NUM_LOG_CALLS {
         raw_image_data[i] += 1; // Change a single pixel of the image data, just to make sure we transmit something different each time.

The run this in one terminal:

pixi run rerun-release 

and in another:

cargo run -p log_benchmark --release -- --benchmarks image --profile

Findings

In a test where I encode a bunch of uncompressed 1024² RGBA images (tests/rust/log_benchmark/src/image.rs).
I found that by far the slowest part is the IPC encoding of arrow data (yes, this is a release build):

zooming in:

This suggests that if we simply encode the chunks in parallel instead on N cores, we will get a N-times speedup (when the actual logging thread is not the bottleneck).

This also gives a likely reason for the recent regression: we switched from arrow2 to arrow-rs.

Perhaps we could also spend some time optimizing arrow::ipc::writer::StreamWriter

[github-actions]

Web viewer built successfully. If applicable, you should also test it:

• I have tested the web viewer

Result	Commit	Link	Manifest
✅	a558811	https://rerun.io/viewer/pr/10173	+nightly +main

^{Note: This comment is updated whenever you push a commit.}

[nikolausWest]

Really great stuff! So great to see this breakdown so easily.

This suggests that if we simply encode the chunks in parallel instead on N cores, we will get a N-times speedup (when the actual logging thread is not the bottleneck).

We should keep in mind here though that in the user's system, it may not be desirable for the logging to take up all the resources. Don't know what the answer is but this might need to be a setting (using many threads to improve latency is obviously great ion an off-device bridge but perhaps not on device in production).

Perhaps we could also spend some time optimizing arrow::ipc::writer::StreamWriter

Any improvements we can do to the single threaded case would be great in both cases =)

[jprochazk]

I wonder how the changes from this draft affect the measurements here:

• Improve encode perf #9826

Will try it myself soonish

[jprochazk]

The latency metrics are no longer opt-in. We always show them now if they get surprisingly high.
The measurements are made by adding extra metadata to the record batches at IPC encode/decode time.

I would expect this to be part of the "show performance metrics" setting. How much overhead does this add to encode/decode time?

[emilk]

The latency metrics are no longer opt-in. We always show them now if they get surprisingly high.
The measurements are made by adding extra metadata to the record batches at IPC encode/decode time.

I would expect this to be part of the "show performance metrics" setting. How much overhead does this add to encode/decode time?

We need to insert the measurement on the SDK side, without knowing the settings for the viewer. But this is only a single time measurement per chunk, so the added overhead is minimal.

[emilk]

I removed the old "queue latency", which was just measuring the latency from receiving data until ingesting it; which we now cover in another way with the new code

[nikolausWest]

Perhaps a bit silly but did a Chatgpt deep research to look for opportunities to improve performance. May be something in there of interest

Performance of Arrow StreamWriter in Rerun.pdf

[emilk]