non-deterministic write size after updating

[asubiotto]

Describe the bug

On dacbb25

thread 'tokio-runtime-worker' panicked at /home/runner/.cargo/git/checkouts/vortex-ea6777c0fea02158/07a9644/vortex-buffer/src/buffer.rs:296:13:
range end out of bounds: 157660 <= 157652
Backtrace:
   0: vortex_buffer::buffer::Buffer<T>::slice_with_alignment
             at ./home/runner/.cargo/git/checkouts/vortex-ea6777c0fea02158/07a9644/vortex-buffer/src/buffer.rs:296:13
   1: vortex_buffer::buffer::Buffer<T>::slice
             at ./home/runner/.cargo/git/checkouts/vortex-ea6777c0fea02158/07a9644/vortex-buffer/src/buffer.rs:250:14
   2: vortex_io::file::read::request::CoalescedRequest::resolve
             at ./home/runner/.cargo/git/checkouts/vortex-ea6777c0fea02158/07a9644/vortex-io/src/file/read/request.rs:154:40
   3: vortex_io::file::read::request::IoRequest::resolve
             at ./home/runner/.cargo/git/checkouts/vortex-ea6777c0fea02158/07a9644/vortex-io/src/file/read/request.rs:87:51
   4: <vortex_io::file::object_store::ObjectStoreIoSource as vortex_io::file::read::source::ReadSource>::drive_send::{{closure}}::{{closure}}
             at ./home/runner/.cargo/git/checkouts/vortex-ea6777c0fea02158/07a9644/vortex-io/src/file/object_store.rs:152:34
   5: vortex_io::runtime::handle::Handle::spawn::{{closure}}
             at ./home/runner/.cargo/git/checkouts/vortex-ea6777c0fea02158/07a9644/vortex-io/src/runtime/handle.rs:70:37
   6: <core::pin::Pin<P> as core::future::future::Future>::poll
             at ./rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/future/future.rs:124:9
   7: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
             at ./home/runner/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/instrument.rs:321:15
   8: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}
             at ./home/runner/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/runtime/task/core.rs:365:24
   9: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
             at ./home/runner/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/loom/std/unsafe_cell.rs:16:9
  10: tokio::runtime::task::core::Core<T,S>::poll
             at ./home/runner/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/runtime/task/core.rs:354:30
  11: tokio::runtime::task::harness::poll_future::{{closure}}
             at ./home/runner/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/runtime/task/harness.rs:535:30
  12: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at ./rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/panic/unwind_safe.rs:272:9
  13: std::panicking::catch_unwind::do_call
             at ./rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:589:40
  14: std::panicking::catch_unwind
             at ./rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:552:19
  15: std::panic::catch_unwind[
             at ./rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panic.rs:359:14
  16: tokio::runtime::task::harness::poll_future
             at ./home/runner/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/runtime/task/harness.rs:523:18
  17: tokio::runtime::task::harness::Harness<T,S>::poll_inner
             at ./home/runner/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/runtime/task/harness.rs:210:27
  18: tokio::runtime::task::harness::Harness<T,S>::poll
             at ./home/runner/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.1/src/runtime/task/harness.rs:155:20

To Reproduce

No response

Expected behavior

No response

Additional context

No response

[asubiotto]

cc @gatesn

[asubiotto]

This was running smoothly until I upgraded to the commit referenced above and it was happening consistently which makes me think the issue is something changed in vortex.

[robert3005]

what was the previous commit you were using?

[onursatici]

@asubiotto are you also able to share a sample file that reproduces this, and the scan code that triggers this?

[asubiotto]

We were running on aa43cb9 previously. @onursatici I unfortunately don't have a sample file and reproduction. The upgrade had passed all our tests and we started seeing this in prod, so I was focused on resolving/reverting. I'm working on more extensive upgrade tests that will hopefully reproduce it.

[onursatici]

looking into this I couldn't see a bug in the request coalescing logic and alignments, one reason might be that the length of response we are getting from the object store might be less than what we expect, but not sure why that would start to happen after upgrading vortex: #5219

Let us know if you manage to reproduce this, I couldn't on my side yet

[asubiotto]

Sounds good, thanks for looking into it. Yeah, my guess is that something changed with alignment calculations with splits (maybe with the new struct format?) although it's good to have #5219 in any case. Will hopefully be able to reproduce this.

[onursatici]

I have some hunch on what might be happening, it is bit of a reach though. I am assuming you are reading files that were written using old code when hitting this, is that right? Do these files somehow contain a top level nullable struct dtype? I don't think we supported this before but now we do. And if you somehow manage to write a file with a nullable struct dtype using the old code, then new code would fail to read this, because it will look for a validity layout child that was absent on write time, which would mess up the segment map, so it will request segments using a wrong id, resulting in the size mismatch you are seeing

[onursatici]

update on above: Using the default write strategy it was not possible to have nullable top level structs using the old code, so this was not a break

[asubiotto]

Was able to reproduce this on latest develop and it seems like the panic is caused by passing the wrong file size to the scan in with_file_size because we do hit the new object store size error check: Object store stream returned 37916 bytes but expected 38004 bytes (range: 0..38004). The files can be correctly read with the right file size. This started happening after the vortex upgrade but it's still unclear why. This might just be a latent bug on our side that the upgrade somehow revealed. I'll keep on investigating.

[asubiotto]

It seems like the root cause is that vortex writes are non-deterministic and give different sizes for multiple writes of the same data. The reason the upgrade was behind this is that I switched this precise code path to use normal async writes with a multi-threaded tokio handle instead of a single threaded runtime it was using previously (since this was blocking due to what seemed like executor incompatibilities). Is it expected that resulting bytes/sizes are non-deterministic given the same input in vortex? It seems like this doesn't repro on 0.53.0. This test fails for me on latest develop:

#[tokio::test(flavor = "multi_thread", worker_threads = 16)]
async fn test_deterministic_write_size() -> VortexResult<()> {
    const ROWS: usize = 5;

    // Nested metadata struct.
    let metadata_ids: Vec<u64> = (0..ROWS).map(|i| i as u64).collect();
    let metadata_scores: Vec<f32> = (0..ROWS).map(|i| ((i % 100) as f32) / 10.0).collect();
    let metadata = StructArray::from_fields(&[
        ("id", Buffer::from(metadata_ids).into_array()),
        ("score", Buffer::from(metadata_scores).into_array()),
    ])?
    .into_array();

    let chunk = StructArray::from_fields(&[("metadata", metadata)])?.into_array();

    let mut tasks = Vec::new();
    for _ in 0..100 {
        let chunk_clone = chunk.clone();
        tasks.push(tokio::spawn(async move {
            let mut buf = ByteBufferMut::empty();
            SESSION
                .write_options()
                .write(&mut buf, chunk_clone.to_array_stream())
                .await
                .unwrap();
            buf.len()
        }));
    }

    let mut sizes = Vec::new();
    for task in tasks {
        sizes.push(task.await.unwrap());
    }

    let first_size = sizes[0];
    for (i, &size) in sizes.iter().enumerate() {
        assert_eq!(
            size, first_size,
            "Iteration {} produced different size: {} vs {}",
            i, size, first_size
        );
    }

    Ok(())
}

[asubiotto]

Seems like @onursatici is investigating this and it is expected due to probabilistic sampling for compression. I am not sure why this only happens with a new version though. Maybe it just became observable to us because of the struct change.

Happy to close this issue if we're in agreement non-deterministic result sizes are expected.

[robert3005]

I think there's something more going on here. The value differs in length by 8 bytes which is an oddly specific number. We want to get to the bottom of this.

[asubiotto]

Sounds good. FYI we're seeing more than just 8 bytes difference sometimes (88 in the linked comment): #5218 (comment)