Running Clickbench query 18 fails with "failed to fill whole buffer" error

[alamb]

Describe the bug

Even after the fix for

• Panic when ClickBench Q18 with memory limited to 1G: range end index 1943308 out of range for slice of length 193245 #18474

I am trying to run the clickbench benchmark with limited memory and I can't seem to get it to work.

Specifically I would like to run q18

SELECT "UserID", extract(minute FROM to_timestamp_seconds("EventTime")) AS m, "SearchPhrase", COUNT(*) FROM hits GROUP BY "UserID", m, "SearchPhrase" ORDER BY COUNT(*) DESC LIMIT 10;

With only 1G of RAM

To Reproduce

Run this command

cargo run --bin datafusion-cli -- -m 1G -c "SELECT \"UserID\", extract(minute FROM to_timestamp_seconds(\"EventTime\")) AS m, \"SearchPhrase\", COUNT(*) FROM '/Users/andrewlamb/Software/datafusion/benchmarks/data/hits_partitioned' GROUP BY \"UserID\", m, \"SearchPhrase\" ORDER BY COUNT(*) DESC LIMIT 10;"

It fails with this error:
Arrow error: Io error: failed to fill whole buffer

Expected behavior

I expect the command to succeeded

Additional context

No response

[devanshu0987]

devanshu@MACTHVTP9C71N datafusion % datafusion-cli -m 1G -c "SELECT \"UserID\", extract(minute FROM to_timestamp_seconds(\"EventTime\")) AS m, \"SearchPhrase\", COUNT(*) FROM 'benchmarks/data/hits_partitioned' GROUP BY \"UserID\", m, \"SearchPhrase\" ORDER BY COUNT(*) DESC LIMIT 10;"
DataFusion CLI v51.0.0

thread 'tokio-runtime-worker' (53945863) panicked at /Users/devanshu/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/datafusion-physical-plan-51.0.0/src/aggregates/group_values/multi_group_by/bytes_view.rs:466:53:
range end index 2087423 out of range for slice of length 9147
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Error: Join Error
caused by
External error: task 146 panicked with message "range end index 2087423 out of range for slice of length 9147"

devanshu@MACTHVTP9C71N datafusion % datafusion-cli -m 4G -c "SELECT \"UserID\", extract(minute FROM to_timestamp_seconds(\"EventTime\")) AS m, \"SearchPhrase\", COUNT(*) FROM 'benchmarks/data/hits_partitioned' GROUP BY \"UserID\", m, \"SearchPhrase\" ORDER BY COUNT(*) DESC LIMIT 10;"
DataFusion CLI v51.0.0
Error: Arrow error: Io error: failed to fill whole buffer

devanshu@MACTHVTP9C71N datafusion % datafusion-cli -m 8G -c "SELECT \"UserID\", extract(minute FROM to_timestamp_seconds(\"EventTime\")) AS m, \"SearchPhrase\", COUNT(*) FROM 'benchmarks/data/hits_partitioned' GROUP BY \"UserID\", m, \"SearchPhrase\" ORDER BY COUNT(*) DESC LIMIT 10;"
DataFusion CLI v51.0.0
Error: Arrow error: Io error: failed to fill whole buffer

This is replicable on a Local Mac M2 with 16GB RAM.

[Omega359]

On my machine it takes till 8G to encounter the buffer fill error:

bruce@fedora:~/dev/datafusion$ datafusion-cli -m 1G -c "SELECT \"UserID\", extract(minute FROM to_timestamp_seconds(\"EventTime\")) AS m, \"SearchPhrase\", COUNT(*) FROM 'benchmarks/data/hits.parquet' GROUP BY \"UserID\", m, \"SearchPhrase\" ORDER BY COUNT(*) DESC LIMIT 10;"
DataFusion CLI v51.0.0

thread 'tokio-runtime-worker' (59949) panicked at /home/bruce/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/datafusion-physical-plan-51.0.0/src/aggregates/group_values/multi_group_by/bytes_view.rs:466:53:
range end index 2034086 out of range for slice of length 4481
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

thread 'tokio-runtime-worker' (59940) panicked at /home/bruce/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/datafusion-physical-plan-51.0.0/src/aggregates/group_values/multi_group_by/bytes_view.rs:466:53:
range end index 2069630 out of range for slice of length 66557

thread 'tokio-runtime-worker' (59936) panicked at /home/bruce/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/datafusion-physical-plan-51.0.0/src/aggregates/group_values/multi_group_by/bytes_view.rs:466:53:
range end index 1653741 out of range for slice of length 81826

thread 'tokio-runtime-worker' (59946) panicked at /home/bruce/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/datafusion-physical-plan-51.0.0/src/aggregates/group_values/multi_group_by/bytes_view.rs:466:53:
range end index 2030313 out of range for slice of length 636
Error: Join Error
caused by
External error: task 84 panicked with message "range end index 2069630 out of range for slice of length 66557"
bruce@fedora:~/dev/datafusion$ datafusion-cli -m 4G -c "SELECT \"UserID\", extract(minute FROM to_timestamp_seconds(\"EventTime\")) AS m, \"SearchPhrase\", COUNT(*) FROM 'benchmarks/data/hits.parquet' GROUP BY \"UserID\", m, \"SearchPhrase\" ORDER BY COUNT(*) DESC LIMIT 10;"
DataFusion CLI v51.0.0

thread 'tokio-runtime-worker' (60084) panicked at /home/bruce/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/datafusion-physical-plan-51.0.0/src/aggregates/group_values/multi_group_by/bytes_view.rs:466:53:
range end index 2077728 out of range for slice of length 825
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Error: Join Error
caused by
External error: task 44 panicked with message "range end index 2077728 out of range for slice of length 825"
bruce@fedora:~/dev/datafusion$ datafusion-cli -m 8G -c "SELECT \"UserID\", extract(minute FROM to_timestamp_seconds(\"EventTime\")) AS m, \"SearchPhrase\", COUNT(*) FROM 'benchmarks/data/hits.parquet' GROUP BY \"UserID\", m, \"SearchPhrase\" ORDER BY COUNT(*) DESC LIMIT 10;"
DataFusion CLI v51.0.0
Error: Arrow error: Io error: failed to fill whole buffer

[alamb]

Here is the stack frame of the error:

<arrow_schema::error::ArrowError as core::convert::From<std::io::error::Error>>::from error.rs:78
<core::result::Result<T,F> as core::ops::try_trait::FromResidual<core::result::Result<core::convert::Infallible,E>>>::from_residual result.rs:2184
arrow_ipc::reader::MessageReader<R>::maybe_next reader.rs:1744
arrow_ipc::reader::StreamReader<R>::next_ipc_message reader.rs:1581
arrow_ipc::reader::StreamReader<R>::maybe_next reader.rs:1550
<arrow_ipc::reader::StreamReader<R> as core::iter::traits::iterator::Iterator>::next reader.rs:1685
datafusion_physical_plan::spill::SpillReaderStream::poll_next_inner::{{closure}} mod.rs:194
datafusion_common_runtime::trace_utils::trace_block::{{closure}} trace_utils.rs:174
core::ops::function::FnOnce::call_once{{vtable.shim}} function.rs:250
<alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once boxed.rs:2005
datafusion_common_runtime::trace_utils::trace_block::{{closure}} trace_utils.rs:183
core::ops::function::FnOnce::call_once{{vtable.shim}} function.rs:250
<alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once boxed.rs:2005
<tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll task.rs:42
tokio::runtime::task::core::Core<T,S>::poll::{{closure}} core.rs:365
[Inlined] tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut unsafe_cell.rs:16
tokio::runtime::task::core::Core<T,S>::poll core.rs:354
tokio::runtime::task::harness::poll_future::{{closure}} harness.rs:535
...

It appears to be coming from

datafusion/datafusion/physical-plan/src/spill/mod.rs

Lines 106 to 109 in 7c05b20

	fn poll_next_inner(
	&mut self,
	cx: &mut Context<'_>,
	) -> Poll<Option<Result<RecordBatch>>> {

Specifically:

datafusion/datafusion/physical-plan/src/spill/mod.rs

Lines 185 to 204 in 7c05b20

	SpillReaderStreamState::Waiting(_) => {
	// Temporarily replace with `Done` to be able to pass the file to the task.
	let SpillReaderStreamState::Waiting(mut reader) =
	std::mem::replace(&mut self.state, SpillReaderStreamState::Done)
	else {
	unreachable!()
	};
	let task = SpawnedTask::spawn_blocking(move || {
	let next_batch = reader.next().transpose()?;
	Ok((reader, next_batch))
	});
	self.state = SpillReaderStreamState::ReadInProgress(task);
	// Poll again immediately so the inner task is polled and the waker is
	// registered.
	self.poll_next_inner(cx)
	}

[alamb]

Realistically I am not planning on working on this in the near term

[devanshu0987]

Hi @alamb, if it is not too much effort and you have time, would it be possible for you to write a brief document outlining how to reason about this issue and how to debug it? Where to look, what the overall logic is, etc.

I spent some time on it, but since I am a newbie to this codebase/async Rust, I couldn't properly debug the async code and its execution.
I would like to ramp up and would like to come back to this in a couple of months when I have more understanding.

Thanks.

[alamb]

Hi @devanshu0987 -- I probably don't have time to write up the issue as I don't really know what the problem is.

It appears to be a bug in the spill reader -- I think the next steps are to debug it further. The good news is that there is a reproducer so that can probably help (or you can send an AI / LLM after it)