# Std::fs::read slow? **URL:** \ **Category:** help\ **Created:** [December 5, 2022, 6:26pm UTC](https://users.rust-lang.org/t/std-read-slow/85424 "2022-12-05T18:26:25Z")\ **Posts on this page:** 20\ **Page:** 1
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 5, 2022, 6:26pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/1 "2022-12-05T18:26:25Z")
I was benchmarking some code, and noticed how `std::fs::read` was 2X slower than `read()` in Julia. I wrote a terrible alternative that seems to work (besides leaking memory, and maybe being broken in other unexpected ways) but it's approx. 2X faster: > **** > > ```rust > #![feature(allocator_api)] > #![feature(ptr_as_uninit)] > > use std::{alloc::{Layout, Allocator}, time::Instant}; > > use nix::{fcntl::OFlag, sys::stat::Mode}; > use rand::{Rng, distributions::Uniform}; > > fn main() { > let mut rng = rand::thread_rng(); > let mut s = Vec::::new(); > for _ in 0..400_000_000 { > s.push(rng.sample(Uniform::new(0, 26)) + 'a' as u8); > } > let path = "testfile"; > std::fs::write(path, s).unwrap(); > > let tic = Instant::now(); > let f = std::fs::File::open(path).unwrap(); > let n = f.metadata().unwrap().len() as usize; > let a = std::alloc::System; > let layout = Layout::from_size_align(n, 32).unwrap(); > let v = a.allocate(layout).unwrap(); > let fd = nix::fcntl::open(path, OFlag::O_RDONLY, Mode::empty()).unwrap(); > let v1 = unsafe { std::mem::transmute::<_, &mut [u8]>(v.as_uninit_slice_mut()) }; > let x = nix::unistd::read(fd, v1).unwrap(); > assert_eq!(x, n); // I know this can fail > println!("Terrible hack: {:10}µs", tic.elapsed().as_micros()); > > let tic = Instant::now(); > let v2 = std::fs::read(path).unwrap(); > println!("std::fs::read: {:10}µs", tic.elapsed().as_micros()); > > assert_eq!(v1, v2); > } > > ``` Output: ```rust Terrible hack: 67359µs std::fs::read: 142929µs ``` It simply allocates the necessary memory and then does a read syscall. Where does all the additional overhead come from in `std::fs::read`? Could it be improved? Maybe the buffer extension [in the `default_read_to_end`](https://doc.rust-lang.org/src/std/io/mod.rs.html#362) used by `std::fs::read` is too conservative? ---
**Author:** ![wesleywiser](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/wesleywiser/32/7436_2.png) [@wesleywiser](https://users.rust-lang.org/u/wesleywiser)\ **Post date:** [December 5, 2022, 7:27pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/2 "2022-12-05T19:27:10Z")
Interesting question! Let me start by posting the numbers I get on my machine for the code you provided: ```rust $ rustc +nightly --version rustc 1.67.0-nightly (1eb62b123 2022-11-27) $ cargo +nightly run --release Compiling read_test v0.1.0 (/tmp/read_test) Finished release [optimized + debuginfo] target(s) in 0.42s Running `target/release/read_test` Terrible hack: 57107µs std::fs::read: 102822µs ``` Let's see what happens if we switch the order of the test cases: > **Source** > > ```rust > #![feature(allocator_api)] > #![feature(ptr_as_uninit)] > > use std::{alloc::{Layout, Allocator}, time::Instant}; > > use nix::{fcntl::OFlag, sys::stat::Mode}; > use rand::{Rng, distributions::Uniform}; > > fn main() { > let mut rng = rand::thread_rng(); > let mut s = Vec::::new(); > for _ in 0..400_000_000 { > s.push(rng.sample(Uniform::new(0, 26)) + 'a' as u8); > } > let path = "testfile"; > std::fs::write(path, s).unwrap(); > > let tic = Instant::now(); > let v2 = std::fs::read(path).unwrap(); > println!("std::fs::read: {:10}µs", tic.elapsed().as_micros()); > > let tic = Instant::now(); > let f = std::fs::File::open(path).unwrap(); > let n = f.metadata().unwrap().len() as usize; > let a = std::alloc::System; > let layout = Layout::from_size_align(n, 32).unwrap(); > let v = a.allocate(layout).unwrap(); > let fd = nix::fcntl::open(path, OFlag::O_RDONLY, Mode::empty()).unwrap(); > let v1 = unsafe { std::mem::transmute::<_, &mut [u8]>(v.as_uninit_slice_mut()) }; > let x = nix::unistd::read(fd, v1).unwrap(); > assert_eq!(x, n); // I know this can fail > println!("Terrible hack: {:10}µs", tic.elapsed().as_micros()); > > assert_eq!(v1, v2); > } > > ``` ```rust $ cargo +nightly run --release Compiling read_test v0.1.0 (/tmp/read_test) Finished release [optimized + debuginfo] target(s) in 0.41s Running `target/release/read_test` std::fs::read: 59099µs Terrible hack: 96395µs ``` Now they've switched positions and `std::fs::read` is significantly faster than the "terrible hack" implementation! This is a strong sign that we're not actually measuring what we think we're measuring. Let's use [`strace`](https://man7.org/linux/man-pages/man1/strace.1.html) to see what syscalls we actually make: ## `std::fs::read` ```rust clock_gettime(CLOCK_MONOTONIC, {tv_sec=97469, tv_nsec=90079100}) = 0 openat(AT_FDCWD, "testfile", O_RDONLY|O_CLOEXEC) = 3 statx(0, NULL, AT_STATX_SYNC_AS_STAT, STATX_ALL, NULL) = -1 EFAULT (Bad address) statx(3, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_ALL|0x1000, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=400000000, ...}) = 0 lseek(3, 0, SEEK_CUR) = 0 mmap(NULL, 400003072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2331def000 read(3, "oktktftsgibrigcysbdamxxylnyfbqhr"..., 400000000) = 400000000 read(3, "", 32) = 0 close(3) = 0 clock_gettime(CLOCK_MONOTONIC, {tv_sec=97469, tv_nsec=153213700}) = 0 write(1, "std::fs::read: 63134\302\265s\n", 29std::fs::read: 63134µs ``` ## Terrible hack ```rust clock_gettime(CLOCK_MONOTONIC, {tv_sec=97469, tv_nsec=153860400}) = 0 openat(AT_FDCWD, "testfile", O_RDONLY|O_CLOEXEC) = 3 statx(3, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_ALL|0x1000, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=400000000, ...}) = 0 mmap(NULL, 400003072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f231a076000 openat(AT_FDCWD, "testfile", O_RDONLY) = 4 read(4, "oktktftsgibrigcysbdamxxylnyfbqhr"..., 400000000) = 400000000 clock_gettime(CLOCK_MONOTONIC, {tv_sec=97469, tv_nsec=252478000}) = 0 write(1, "Terrible hack: 98617\302\265s\n", 29Terrible hack: 98617µs ``` While there are some slight differences in the exact syscalls made (for a variety of reasons), both basically just boil down to: ```rust allocate enough memory for the file content (via mmap) read all of the file content into memory ``` Given that whichever test case is first runs considerably faster and consists of the same core syscalls, it's reasonable to assume that what is actually happening is that the same operations take different amounts of time (with the first set being faster for some reason and the second set being slower) and that difference is what is being measured. The next step here would be to confirm that via [`perf`](https://man7.org/linux/man-pages/man1/perf.1.html) but I'm currently using WSL and that isn't available on my machine. * * * Note: I believe the "terrible hack" implementation is essentially equivalent to: ```rust use std::{io::Read, time::Instant}; let tic = Instant::now(); let mut f = std::fs::File::open(path).unwrap(); let n = f.metadata().unwrap().len() as usize; let mut v3 = vec![0u8; n]; let x = f.read(&mut v3).unwrap(); assert_eq!(x, n); println!("std::io::Read::read: {:10}µs", tic.elapsed().as_micros()); ``` Which doesn't require 3rd party crates, `unsafe` or unstable features. It produces the following syscalls: ```rust clock_gettime(CLOCK_MONOTONIC, {tv_sec=98081, tv_nsec=272918100}) = 0 openat(AT_FDCWD, "testfile", O_RDONLY|O_CLOEXEC) = 5 statx(5, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_ALL|0x1000, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=400000000, ...}) = 0 mmap(NULL, 400003072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fddf6880000 read(5, "oktktftsgibrigcysbdamxxylnyfbqhr"..., 400000000) = 400000000 clock_gettime(CLOCK_MONOTONIC, {tv_sec=98081, tv_nsec=399405200}) = 0 write(1, "std::io::Read::read_to_end: "..., 42std::io::Read::read_to_end: 126487µs ``` With similar performance characteristics to the others depending on which implementation runs first in the program. ---
**Author:** ![Coding-Badly](https://avatars.discourse-cdn.com/v4/letter/c/58956e/32.png) [@Coding-Badly](https://users.rust-lang.org/u/Coding-Badly)\ **Post date:** [December 5, 2022, 7:38pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/3 "2022-12-05T19:38:39Z")
> [@ambiso](#): > > Maybe the buffer extension [in the `default_read_to_end`](https://doc.rust-lang.org/src/std/io/mod.rs.html#362) used by `std::fs::read` is too conservative? That call is essentially saying "I need at least 32 more bytes but you add what you believe is best." Eventually execution ends up [here](https://github.com/rust-lang/rust/blob/74fbbefea8d13683cca5eee62e4740706cb3144a/library/alloc/src/raw_vec.rs#L374-L404) which essentially doubles the size. ---
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 5, 2022, 7:54pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/4 "2022-12-05T19:54:58Z")
> [@wesleywiser](#): > > Now they've switched positions and `std::fs::read` is significantly faster than the "terrible hack" implementation! This is a strong sign that we're not actually measuring what we think we're measuring. I strongly believe this is a fluke (have you tried running it again and checking if you consistently get this result?), but I will provide a criterion benchmark to prove it: > **[GitHub - ambiso/read\_slow](https://github.com/ambiso/read_slow)** > > Contribute to ambiso/read\_slow development by creating an account on GitHub. It doesn't matter what order you arrange the benchmarks in, the terrible hack is consistently more than twice as fast as std::fs::read. I've also added the version that the terrible hack is supposedly equivalent to and it is as slow as `std::fs::read`. Maybe the speed difference comes from not initializing the memory to zero? Benchmark report: ![image](https://us1.discourse-cdn.com/flex019/uploads/rust_lang/original/3X/7/8/787b997a25f963657726752d321b23f5f737b7e6.png) ![image](https://us1.discourse-cdn.com/flex019/uploads/rust_lang/original/3X/e/f/ef01ae56121be3d79508d9ec6a102641aaf01e2c.png) ---
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 5, 2022, 8:12pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/5 "2022-12-05T20:12:47Z")
It's probably not called at all - both versions just perform a single read syscall to read the entire file. ---
**Author:** ![CAD97](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/cad97/32/5076_2.png) [@CAD97](https://users.rust-lang.org/u/CAD97)\ **Post date:** [December 5, 2022, 9:08pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/6 "2022-12-05T21:08:53Z")
I _suspect_ that the removed overhead in the "terrible hack" version will amount to the extra work to ensure both soundness and completeness of the read operation. I'm not using a \*nix, so I'll likely get vastly different results from the Windows filesystem, so everything here is pure conjecture. Note that `File` uses [its own `read_to_end`](https://doc.rust-lang.org/nightly/std/fs/struct.File.html#method.read_to_end-1) implementation, not the default provided one, which [does](https://doc.rust-lang.org/nightly/src/std/fs.rs.html#802-805) add a reserve for `file.metadata()?.len() - file.stream_position()?`, and it doesn't zero the memory before reading to it. Given the 2x performance difference, I suspect the difference comes down to some combination of exactly the `read(3, _, 32)` [[source]](https://doc.rust-lang.org/nightly/src/std/io/mod.rs.html#396-412) done to ensure the entire file was in fact read, and the `close(3)` to release the file handle, both not done by the hack version. The impact of the file close can be tested by open-coding `fs::read` a bit to get ```rust // fs::read let start = Instant::now(); let end; let bytes = { let mut file = File::open(path)?; let mut bytes = Vec::new(); file.read_to_end(&mut bytes)?; Ok(bytes) }; end = Instant::now(); // stop timing before closing the file let start = Instant::now(); let end; let bytes = { let mut file = File::open(path)?; let mut bytes = Vec::new(); file.read_to_end(&mut bytes)?; end = Instant::now(); Ok(bytes) }; ``` The second `read` can't _really_ be avoided; the way that you determine that you've read the entire file _is_ to get `read(..) == 0`. However, if you're willing to assume that the file contains the exact number of bytes the metadata says (not actually fully guaranteed), you can use something along the lines of ```rust let start = Instant::now(); let end; let bytes = { let mut file = File::open(path)?; let mut bytes = Vec::new(); bytes.resize(file.metadata()?.len(), 0); file.read_exact(&mut bytes)?; Ok(bytes) }; end = Instant::now(); ``` to not do the extra EOF check. On nightly, we can use `read_buf_exact` to avoid the need to zero-fill the vector first, but then you also need to unsafely communicate that size increase back to the `vec`. The reason for the "whichever first" behavior observed for @wesleywiser may be due to that the file handles used for the single-file test are never actually released. This means the first test is done on a file handle that is the only one using the actual file, whereas the second test is done with two file handles open to the same file. This may impact OS read performance. ---
**Author:** ![wesleywiser](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/wesleywiser/32/7436_2.png) [@wesleywiser](https://users.rust-lang.org/u/wesleywiser)\ **Post date:** [December 5, 2022, 9:23pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/7 "2022-12-05T21:23:59Z")
Yes, I ran the results multiple times and consistently see the first test case being the faster one for the program you gave. * * * Here's my criterion setup: > **Source** > > ```rust > #![feature(allocator_api)] > #![feature(ptr_as_uninit)] > > use std::{alloc::{Layout, Allocator}}; > > use nix::{fcntl::OFlag, sys::stat::Mode}; > use rand::{Rng, distributions::Uniform}; > use criterion::{black_box, criterion_group, criterion_main, Criterion}; > > pub fn criterion_benchmark(c: &mut Criterion) { > let mut rng = rand::thread_rng(); > let mut s = Vec::::new(); > for _ in 0..40_000_000 { > s.push(rng.sample(Uniform::new(0, 26)) + 'a' as u8); > } > let path = "testfile"; > std::fs::write(path, s).unwrap(); > > c.bench_function("std::fs::read", |b| b.iter(|| { > std::fs::read(path).unwrap(); > })); > > c.bench_function("terrible hack", |b| b.iter(|| { > let f = std::fs::File::open(path).unwrap(); > let n = f.metadata().unwrap().len() as usize; > let a = std::alloc::System; > let layout = Layout::from_size_align(n, 32).unwrap(); > let v = a.allocate(layout).unwrap(); > let fd = nix::fcntl::open(path, OFlag::O_RDONLY, Mode::empty()).unwrap(); > let v1 = unsafe { std::mem::transmute::<_, &mut [u8]>(v.as_uninit_slice_mut()) }; > let x = nix::unistd::read(fd, v1).unwrap(); > assert_eq!(x, n); // I know this can fail > })); > } > > criterion_group!(benches, criterion_benchmark); > criterion_main!(benches); > > ``` I had to lower the amount of data substantially in order for the benchmark to not run out of memory. The results I have are ![image](https://us1.discourse-cdn.com/flex019/uploads/rust_lang/original/3X/8/9/8955c7877ae4a511b67fefd347ab4887f490dfad.png) ![image](https://us1.discourse-cdn.com/flex019/uploads/rust_lang/original/3X/8/a/8a2da954f36fdb6544a45326799bf693402d1368.png) Showing that the "terrible hack" approach is 50% slower. Interestingly, if I flip the order this time, the results remain constant. I finished the implementation so that it closes the file handle and frees the allocated memory and this brings both implementations to essentially the same performance: ```diff diff --git a/benches/my_benchmark.rs b/benches/my_benchmark.rs index 7d6d60e..fac33b2 100644 --- a/benches/my_benchmark.rs +++ b/benches/my_benchmark.rs @@ -27,6 +27,8 @@ pub fn criterion_benchmark(c: &mut Criterion) { let v1 = unsafe { std::mem::transmute::<_, &mut [u8]>(v.as_uninit_slice_mut()) }; let x = nix::unistd::read(fd, v1).unwrap(); assert_eq!(x, n); // I know this can fail + nix::unistd::close(fd).unwrap(); + unsafe { a.deallocate(v.as_non_null_ptr(), layout); } })); ``` ![image](https://us1.discourse-cdn.com/flex019/uploads/rust_lang/original/3X/1/5/1549d53b5b9bd57932d518be58ab7cfd6041b59c.png) ![image](https://us1.discourse-cdn.com/flex019/uploads/rust_lang/original/3X/7/c/7c837064f9a6a8e3702c6ac037f6a00bd8a0e2c1.png) ---
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 5, 2022, 11:42pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/8 "2022-12-05T23:42:14Z")
> [@wesleywiser](#): > > Yes, I ran the results multiple times and consistently see the first test case being the faster one for the program you gave. Interesting! I wonder if Windows Defender could have an impact on this? Are you using WSL1 or 2? > [@wesleywiser](#): > > I had to lower the amount of data substantially in order for the benchmark to not run out of memory. In the benchmarked version I constructed a `Vec` from the pointer so it would deallocate it (but the optimizer also shouldn't get too trigger happy). See [here](https://github.com/ambiso/read_slow/blob/00a37653bbda72398dae6a6e47a5e8da4d2d195f/benches/my_benchmark.rs#L26). > [@wesleywiser](#): > > I finished the implementation so that it closes the file handle and frees the allocated memory and this brings both implementations to essentially the same performance: I ran your exact benchmark code with those two changes applied (and a `#![feature(slice_ptr_get)]` that was required) and the difference persists: ```rust std::fs::read time: [13.659 ms 13.687 ms 13.719 ms] change: [-2.0217% -1.7758% -1.5177%] (p = 0.00 < 0.05) Performance has improved. Found 5 outliers among 100 measurements (5.00%) 3 (3.00%) high mild 2 (2.00%) high severe terrible hack time: [4.7017 ms 4.7245 ms 4.7487 ms] change: [+12.606% +13.292% +13.918%] (p = 0.00 < 0.05) Performance has regressed. Found 2 outliers among 100 measurements (2.00%) 1 (1.00%) high mild 1 (1.00%) high severe ``` ---
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 6, 2022, 12:39am UTC](https://users.rust-lang.org/t/std-read-slow/85424/9 "2022-12-06T00:39:06Z")
I've implemented the [probing `read`](https://github.com/ambiso/read_slow/blob/8d6e14305c5d9d28b9d215280032832e3a2d53c8/benches/my_benchmark.rs#L28-L34) done by `read_to_end` and closed the file-descriptor, but see no major change in performance. ```rust Benchmarking std::fs::read: Warming up for 3.0000 s Warning: Unable to complete 100 samples in 5.0s. You may wish to increase target time to 12.1s, or reduce sample count to 40. std::fs::read time: [124.72 ms 125.37 ms 126.03 ms] change: [-1.0061% -0.3735% +0.2542%] (p = 0.23 > 0.05) No change in performance detected. terrible hack time: [44.982 ms 45.112 ms 45.242 ms] change: [-1.7500% -1.4790% -1.1734%] (p = 0.00 < 0.05) Performance has improved. Found 1 outliers among 100 measurements (1.00%) 1 (1.00%) high mild Benchmarking safe hack: Warming up for 3.0000 s Warning: Unable to complete 100 samples in 5.0s. You may wish to increase target time to 12.2s, or reduce sample count to 40. safe hack time: [121.75 ms 121.92 ms 122.10 ms] change: [-5.5431% -5.2293% -4.9523%] (p = 0.00 < 0.05) Performance has improved. Found 7 outliers among 100 measurements (7.00%) 7 (7.00%) high mild ``` ---
**Author:** ![CAD97](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/cad97/32/5076_2.png) [@CAD97](https://users.rust-lang.org/u/CAD97)\ **Post date:** [December 6, 2022, 1:17am UTC](https://users.rust-lang.org/t/std-read-slow/85424/10 "2022-12-06T01:17:41Z")
> [@ambiso](#): > > In the benchmarked version I constructed a `Vec` from the pointer so it would deallocate it (but the optimizer also shouldn't get too trigger happy). Don't mix `System` and `Global` (used by default by `Vec`). This is _at best_ relying on nobody using `#[global_allocator]`, and likely actually UB. * * * I've reproduced your `nix` implementation and provided a std implementation that _should_ be identical; it would be nice if you could compare the two for us, and even better if you can get some sort of flamegraph/profiler on it. Note that I've put these into functions; keep them as such to ensure that the harness around them treats them as similarly as possible. > **nix** > > ```rust > fn nix_read(path: &str) -> Vec { > let len = { > let f = File::open(path).unwrap(); > f.metadata().unwrap().len() as usize > }; > > let layout = Layout::from_size_align(len, 1).unwrap(); > let ptr = Global.allocate(layout).unwrap(); > > let fd = nix::fcntl::open(path, OFlag::O_RDONLY, Mode::empty()).unwrap(); > > let did_read = nix::unistd::read(fd, unsafe { ptr.as_mut() }).unwrap(); > assert_eq!(did_read, len); // could fail > > let mut probe_buf = [0u8; 32]; > let did_read = nix::unistd::read(fd, &mut probe_buf).unwrap(); > assert_eq!(did_read, 0); > > nix::unistd::close(fd).unwrap(); > > Box::from_raw(ptr).into() > } > > ``` > > * * * > **std** > > ```rust > fn std_read(path: &str) -> Vec { > let mut f = File::open(path).unwrap(); > let len = f.metadata().unwrap().len() as usize; > > let mut buf = Vec::with_capacity(len); > > let p = ptr::slice_from_raw_parts_mut(buf.as_mut_ptr(), len); > > let did_read = f.read(unsafe { &mut *p }).unwrap(); > assert_eq!(did_read, len); // could fail > > let mut probe_buf = [0u8; 32]; > let did_read = f.read(&mut probe_buf).unwrap(); > assert_eq!(did_read, 0); > > drop(f); > > unsafe { buf.set_len(len) }; > buf > } > > ``` > > * * * These _should_ be doing the exact same thing in both cases\[1\]. If they don't, investigating that is a good avenue to figure out what's going on. * * * 1. Caveat: the nix version actually opens the file twice, since we open it separately to get the metadata than to do the read. ---
**Author:** ![jkugelman](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/jkugelman/32/15839_2.png) [@jkugelman](https://users.rust-lang.org/u/jkugelman)\ **Post date:** [December 6, 2022, 2:59am UTC](https://users.rust-lang.org/t/std-read-slow/85424/11 "2022-12-06T02:59:04Z")
> [@CAD97](#): > > Note that `File` uses [its own `read_to_end`](https://doc.rust-lang.org/nightly/std/fs/struct.File.html#method.read_to_end-1) implementation, not the default provided one, which [does](https://doc.rust-lang.org/nightly/src/std/fs.rs.html#802-805) add a reserve for `file.metadata()?.len() - file.stream_position()?`, and it doesn't zero the memory before reading to it. > > Given the 2x performance difference, I suspect the difference comes down to some combination of exactly the `read(3, _, 32)` [[source]](https://doc.rust-lang.org/nightly/src/std/io/mod.rs.html#396-412) done to ensure the entire file was in fact read, and the `close(3)` to release the file handle, both not done by the hack version. > [@CAD97](#): > > The second `read` can't _really_ be avoided; the way that you determine that you've read the entire file _is_ to get `read(..) == 0`. What an excellent and concise dive into how `File::read_to_end` works. I couldn't have done it better, and I wrote it ([1](https://github.com/rust-lang/rust/pull/89582), [2](https://github.com/rust-lang/rust/pull/89165)). ---
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 6, 2022, 12:43pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/12 "2022-12-06T12:43:22Z")
> [@CAD97](#): > > Don't mix `System` and `Global` (used by default by `Vec`). > > This is _at best_ relying on nobody using `#[global_allocator]`, and likely actually UB. Yup, though you could pass the used allocator (`System`) as the `A` generic parameter of `Vec`. > [@CAD97](#): > > I've reproduced your `nix` implementation and provided a std implementation that _should_ be identical; it would be nice if you could compare the two for us, and even better if you can get some sort of flamegraph/profiler on it. > > Note that I've put these into functions; keep them as such to ensure that the harness around them treats them as similarly as possible. I've had to make minor adjustments to the nix version to make it compile: ```rust 8c8 < let ptr = Global.allocate(layout).unwrap(); --- > let mut ptr = Global.allocate(layout).unwrap(); 20,21c20,21 < < Box::from_raw(ptr).into() --- > > unsafe { Box::from_raw(ptr.as_ptr()).into() } ``` The version you provided performs similarly to the std version: ```rust nix_read time: [118.09 ms 118.20 ms 118.32 ms] std_read time: [120.75 ms 121.20 ms 121.65 ms] ``` * * * But! When I change the alignment of the allocation back to 32 as in my original code I get the speed difference again! ```rust < let layout = Layout::from_size_align(len, 1).unwrap(); --- > let layout = Layout::from_size_align(len, 32).unwrap(); ``` ```rust nix_read time: [42.812 ms 42.884 ms 42.964 ms] std_read time: [118.98 ms 119.07 ms 119.18 ms] ``` Alternatively, I can augment the `std_read` with a custom allocator that always aligns to at least 32 bytes: ```rust pub struct MyAlloc; unsafe impl Allocator for MyAlloc { fn allocate(&self, layout: Layout) -> Result, std::alloc::AllocError> { Global.allocate(unsafe { Layout::from_size_align_unchecked(layout.size(), layout.align().max(32)) }) } unsafe fn deallocate(&self, ptr: std::ptr::NonNull, layout: Layout) { Global.deallocate(ptr, unsafe { Layout::from_size_align_unchecked(layout.size(), layout.align().max(32)) }) } } pub fn std_read(path: &str) -> Vec { let mut f = File::open(path).unwrap(); let len = f.metadata().unwrap().len() as usize; let mut buf = Vec::with_capacity_in(len, MyAlloc{}); let p = std::ptr::slice_from_raw_parts_mut(buf.as_mut_ptr(), len); let did_read = f.read(unsafe { &mut *p }).unwrap(); assert_eq!(did_read, len); // could fail let mut probe_buf = [0u8; 32]; let did_read = f.read(&mut probe_buf).unwrap(); assert_eq!(did_read, 0); drop(f); unsafe { buf.set_len(len) }; buf } ``` This yields the same improvement: ```rust nix_read time: [42.189 ms 42.221 ms 42.255 ms] change: [-1.3588% -1.1494% -0.9741%] (p = 0.00 < 0.05) Change within noise threshold. Found 4 outliers among 100 measurements (4.00%) 3 (3.00%) high mild 1 (1.00%) high severe std_read time: [42.265 ms 42.317 ms 42.370 ms] change: [-65.695% -65.606% -65.511%] (p = 0.00 < 0.05) Performance has improved. Found 2 outliers among 100 measurements (2.00%) 2 (2.00%) high mild ``` An alignment of 16 bytes is not sufficient: ```rust std_read time: [121.59 ms 122.08 ms 122.57 ms] change: [+187.19% +188.48% +189.64%] (p = 0.00 < 0.05) Performance has regressed. Found 1 outliers among 100 measurements (1.00%) 1 (1.00%) high mild ``` ---
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 6, 2022, 5:04pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/13 "2022-12-06T17:04:34Z")
So I tested the std\_read 1 byte aligned vs 32 byte aligned version on my desktop and laptop ([commit](https://github.com/ambiso/read_slow/commit/253a7d0e1cf7727dff16041f045b6fae7f3bdb25)), and on my laptop I cannot reproduce the difference in performance. ### Desktop (AMD Ryzen 9 5900X) ```rust std_read 1 byte aligned time: [133.72 ms 134.03 ms 134.37 ms] std_read 32 byte aligned time: [42.969 ms 43.137 ms 43.306 ms] ``` ### Laptop: (AMD Ryzen 7 PRO 3700U) ```rust std_read 1 byte aligned time: [101.60 ms 101.86 ms 102.16 ms] std_read 32 byte aligned time: [101.98 ms 102.41 ms 102.88 ms] ``` The systems are OS wise very similar, and both use [`amd-ucode`](https://wiki.archlinux.org/title/microcode). Interestingly the 1 byte aligned version on the desktop is slower than the laptop! I've also tested it on a Raspberry Pi and an Intel VPS, both show no major differences: ### Raspberry Pi 3 Model B Rev 1.2 ```rust std_read 1 byte aligned time: [1.6450 s 1.6722 s 1.7206 s] std_read 32 byte aligned time: [1.6606 s 1.6759 s 1.6939 s] ``` ### VPS (Intel Xeon) ```rust std_read 1 byte aligned time: [278.47 ms 291.78 ms 307.45 ms] std_read 32 byte aligned time: [276.78 ms 286.73 ms 297.45 ms] ``` ## Summary It seems like only the system with the AMD Ryzen 9 5900X is affected - maybe others with a Ryzen 5000 series CPU could try the benchmark on their system and see if they get similar results? The code is here: [GitHub - ambiso/read\_slow](https://github.com/ambiso/read_slow) ---
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 6, 2022, 5:44pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/14 "2022-12-06T17:44:56Z")
I tried it on Windows (native, no WSL) with the Ryzen 9 5900X and got no significant difference: ```rust std_read 1 byte aligned time: [75.739 ms 77.823 ms 80.110 ms] std_read 32 byte aligned time: [76.191 ms 78.025 ms 79.979 ms] ``` Interestingly, it's not close to any of the times seen before. This made me suspect it might be related to the filesystem (btrfs) or encryption layer (cryptsetup). I moved the project to a ramdisk: ```sh mkdir /mnt/tmp sudo mount -t tmpfs -o size=10g tmpfs /mnt/tmp cp -r read_slow /mnt/tmp cd /mnt/tmp/read_slow cargo bench ``` But the performance difference persists: ```rust std_read 1 byte aligned time: [121.24 ms 121.34 ms 121.45 ms] std_read 32 byte aligned time: [46.605 ms 46.737 ms 46.877 ms] ``` Note that the ~45-ish milliseconds (~8.6GB/s) I keep getting with the 32 byte aligned version already far surpass the read throughput of my NVMe SSD (3.5GB/s, PCIe 3.0 x4 can also not deliver much more), so the file is most likely completely cached in any case. The ~120ms are just about 3.3GB/s, so I thought maybe it's actually re-reading the file in that case, but I `watch`ed the output of `sudo smartctl -A /dev/nvme0` and the value of `Data Units Read` stays constant throughout the benchmark. > [@CAD97](#): > > even better if you can get some sort of flamegraph/profiler on it. Here's a flamegraph of both versions using `cargo flamegraph -F 50000`: (edit: I have to download them and open them from the filesystem to get interactivity in firefox/chromium) [std\_read](https://raw.githubusercontent.com/ambiso/read_slow/main/std_read.svg) [std\_read\_32\_byte\_aligned](https://raw.githubusercontent.com/ambiso/read_slow/main/std_read_32_byte_aligned.svg) This is profiling the following `main`: ```rust use read_slow::{std_read, std_read_32_byte_aligned}; fn main() { let path = "testfile"; for _ in 0..100 { // depending on the version... // std_read(path); std_read_32_byte_aligned(path); } } ``` You can also grab the raw perf data here: [std\_read perf.data](https://github.com/ambiso/read_slow/blob/main/std_read_perf.data) [std\_read\_32\_byte\_aligned perf.data](https://github.com/ambiso/read_slow/blob/main/std_read_32_byte_aligned_perf.data) ---
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 6, 2022, 7:33pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/15 "2022-12-06T19:33:29Z")
Okay so this is becoming quite the rabbit hole... # Alignment doesn't matter but offset into an allocation (or page?) does This C code measures how long the read syscall takes, based on how far the buf pointer is offset. I got the idea because Julia's `read` doesn't 32-byte align its allocations/pointers either, and still gets the faster 45ms reads. > **** > > ```C > #include > #include > #include > #include > #include > #include > #include > > int64_t millis() > { > struct timespec now; > timespec_get(&now, TIME_UTC); > return ((int64_t) now.tv_sec) * 1000 + ((int64_t) now.tv_nsec) / 1000000; > } > > int main() { > puts("offset milliseconds"); > for (int off = 0; off < 100; ++off) { > int fd = open("testfile", O_RDONLY); > size_t n = 400000000; > char *buf = malloc(n + 4096); > int64_t a = millis(); > if (n != read(fd, buf+off, n)) { > puts("oops"); > } > int64_t b = millis(); > free(buf); > close(fd); > printf("% 3d % 5d\n", off, b - a); > } > } > > ``` Output: ```rust offset milliseconds 0 133 1 132 2 132 3 133 4 131 5 131 6 133 7 134 8 134 9 133 10 133 11 132 12 132 13 131 14 130 15 130 16 46 17 48 18 47 19 47 20 47 21 48 22 48 23 47 24 47 25 47 26 48 ``` So starting with an offset of 16 into the allocation, the read takes ~45ms instead of ~130ms. # What?! Well that's not the best part yet! This pattern stays constant until shortly before the next page boundary! ```rust offset milliseconds 4071 45 4072 45 4073 45 4074 45 4075 45 4076 46 4077 46 4078 46 4079 46 4080 46 4081 129 //!<-- suddenly slow again! 4082 127 4083 125 4084 125 4085 125 4086 125 4087 125 4088 125 4089 126 4090 126 4091 128 4092 126 4093 126 4094 125 4095 125 4096 126 4097 126 4098 126 4099 129 4100 129 4101 130 4102 131 4103 131 4104 132 4105 131 4106 131 4107 133 4108 133 4109 134 4110 133 4111 131 4112 45 //!<-- and fast again! 4113 45 4114 46 4115 45 4116 46 4117 46 4118 46 4119 46 4120 46 4121 45 4122 45 4123 46 ``` This is crazy to me. I guess it might be time to try to debug the Linux kernel? ---
**Author:** ![H2CO3](https://avatars.discourse-cdn.com/v4/letter/h/b5ac83/32.png) [@H2CO3](https://users.rust-lang.org/u/H2CO3)\ **Post date:** [December 6, 2022, 7:42pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/16 "2022-12-06T19:42:30Z")
4080 == 4096 - 16, and 4112 == 4096 + 16. Looks suspicious. Is the allocator maybe using the first/last 16 bytes of each 4k (?) page for bookkeeping? Smells like two pointers in a doubly-linked freelist… And if that's indeed the case, perhaps your page is only 16-but-not-32-byte-aligned, and after all, it's the 32-byte alignment that matters (for some other, even deeper reason)? Or perhaps the prefetcher learned the pattern that it should keep all but the last 16 bytes in the cache (since allocations are cold relative to actual use of the allocated buffer), or maybe its exact opposite (it learned to keep the first 16 bytes hot, since it's the allocator's)? ---
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 6, 2022, 8:09pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/17 "2022-12-06T20:09:43Z")
> [@H2CO3](#): > > each 4k (?) page Yes, 4KiB pages. > [@H2CO3](#): > > perhaps your page is only 16-but-not-32-byte-aligned The page should always be "aligned" to 4096 bytes I think? But I'm also not sure. I think all pages should in principle at least have the same alignment. > [@H2CO3](#): > > 4080 == 4096 - 16, and 4112 == 4096 + 16. Looks suspicious. Assuming that pages are 4096 byte aligned, the pointer I get from malloc is already offset by 16 bytes from the page boundary (probably two 8 byte pointers preceding the allocation) So the read seems to become fast once the destination address is at least 32 bytes into a page. I profiled the kernel with `sudo perf record -g ./a.out`. The output of `perf report` can be seen here: ![image](https://us1.discourse-cdn.com/flex019/uploads/rust_lang/original/3X/e/1/e16a0b759cf9ab7863180c694c6179e2f40929f0.png) Left: fast version with a 32 byte offset into the page Right: slow version with a 16 byte offset into the page it seems the `copy_user_enhanced_fast_string` is responsible for the slow-down (it has a much higher `Self` percentage on the right). That's this function: [https://github.com/torvalds/linux/blob/master/arch/x86/lib/copy\_user\_64.S#L149-L176](https://github.com/torvalds/linux/blob/master/arch/x86/lib/copy_user_64.S#L149-L176) ---
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 6, 2022, 9:30pm UTC](https://users.rust-lang.org/t/std-read-slow/85424/18 "2022-12-06T21:30:54Z")
Jemalloc can be used as a workaround, since it doesn't typically yield pointers that are close to a page boundary: ![image](https://us1.discourse-cdn.com/flex019/uploads/rust_lang/original/3X/8/8/886c82dc347715b4a453715d9ecf11c225affc9b.jpeg) Left: malloc, being slow without adding an additional offset \>= 16 to the buffer pointer before calling read() Right: jemalloc being always fast ---
**Author:** ![ambiso](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/ambiso/32/10843_2.png) [@ambiso](https://users.rust-lang.org/u/ambiso)\ **Post date:** [December 8, 2022, 11:01am UTC](https://users.rust-lang.org/t/std-read-slow/85424/19 "2022-12-08T11:01:09Z")
I was able to reproduce the behavior on another Linux system using a Ryzen 9 5900X so it's not just me! I wasn't able to reproduce it on a 7900X or an EPYC 7513. ---
**Author:** ![system](https://sea1.discourse-cdn.com/flex019/user_avatar/users.rust-lang.org/system/32/51372_2.png) [@system](https://users.rust-lang.org/u/system)\ **Post date:** [March 8, 2023, 11:01am UTC](https://users.rust-lang.org/t/std-read-slow/85424/20 "2023-03-08T11:01:10Z")
This topic was automatically closed 90 days after the last reply. We invite you to open a new topic if you have further questions or comments.