File reading: Performance regression on 0.2.0-alpha.6 compared to 0.1.22

[wandhydrant]

Version

0.2.0-alpha.6 / 0.1.22, on Rust 1.39 in release mode

Platform

Linux [hostname] 4.19.0-6-amd64 #1 SMP Debian 4.19.67-2+deb10u1 (2019-09-20) x86_64 GNU/Linux

Description

For learning, I played around with different versions of buffer-reading a file and counting its bytes. The sync version and a version using Tokio 0.1.22 are both fast, but the async/await version 0.2.0-alpha.6 is 5 to 6 times slower, spending a lot of time in kernel space. While discussing this in the forum it has been suggested to me to report this here as a possible bug in Tokio's executor.

This synchronous version spends on my system 8-16 ms in userland and 95-120 ms in kernel space (as measured by time) after some runs, so that the entire file of 636 MB is in the buffer cache:

use std::fs::File;
use std::io::Read;
use std::time::SystemTime;

static FILEPATH: &str = "/home/vh/tmp/CentOS-7-x86_64-Minimal-1503-01.iso";

fn main() {
    let time = SystemTime::now();
    let mut counter: usize = 0;
    let mut file = File::open(FILEPATH).unwrap();
    let mut buf = [0u8; 16*1024];
    loop {
        match file.read(&mut buf) {
            Ok(n) => {
                if n == 0 {
                    // eof
                    break;
                } else {
                    counter += n;
                }
            },
            Err(_) => panic!("Error while reading file")
        }
    }
    println!("Read {} bytes in {} µs", counter,
             time.elapsed().unwrap().as_micros());
}

And this async version using tokio::fs::File and Tokio 0.1.22 is just as efficient.

extern crate futures; // 0.1.29
extern crate tokio; // 0.1.22

use futures::{Async, Future, try_ready};
use std::time::SystemTime;
use tokio::prelude::{AsyncRead};

static FILEPATH: &str = "/home/vh/tmp/CentOS-7-x86_64-Minimal-1503-01.iso";

fn main() {
    let task = tokio::fs::File::open(FILEPATH)
        .and_then(|mut file| {
            let time = SystemTime::now();
            let mut counter: usize = 0;
            let mut buf = [0u8; 16*1024];
            loop {
                let bytes_read = try_ready!(file.poll_read(&mut buf));
                if bytes_read == 0 {
                    println!("Read {} bytes in {} µs.", counter,
                             time.elapsed().unwrap().as_micros());
                    break;
                } else {
                    counter += bytes_read;
                }
            }
            Ok(Async::Ready(()))
        }).map(|_res| ())
        .map_err(|err| eprintln!("IO error: {:?}", err));
    tokio::run(task);
}

But this modern async version with 0.2.0-alpha.6 takes 220-320 ms in userland and 345-500 ms in kernel space!

extern crate futures; // 0.3.1
extern crate tokio; // 0.2.0-alpha.6

use futures::executor::block_on;
use std::time::SystemTime;
use tokio::fs::File;
use tokio::io::AsyncReadExt;

static FILEPATH: &str = "/home/vh/tmp/CentOS-7-x86_64-Minimal-1503-01.iso";

async fn async_main() {
    let time = SystemTime::now();
    let mut file = File::open(FILEPATH).await.unwrap();
    let mut counter: usize = 0;
    let mut buf = [0u8; 16*1024];
    loop {
        match file.read(&mut buf).await {
            Ok(n) => {
                if n == 0 {
                    // eof
                    break;
                } else {
                    counter += n;
                }
            },
            Err(_) => panic!("Error while reading file")
        }
    }
    println!("Read {} bytes in {} µs.", counter,
             time.elapsed().unwrap().as_micros());   
}

fn main() {
    block_on(async_main());
}

I hope this is not due to some obvious mistake on my part. Thanks!

[carllerche]

Thanks for calling this out. There is a known performance regression that is temporary. The old strategy for fs ops has not been fully hooked into Tokio 0.2.

In short, fs ops should use block_in_place but don’t yet (they did in 0.1, but the scheduler was fully rewritten and not everything is fully hooked up.

[nicholasbishop]

Until this is fixed, is there a recommended workaround? Is it best to just call the sync functions in std::fs, or is there a better method?

[carllerche]

You can call block_in_place yourself and use std::fs.

[carllerche]

Roughly:

tokio::task::block_in_place(|| {
    std::fs::File::open(...)
})

[nicholasbishop]

I gave that a try but got a runtime error:

thread 'main' panicked at 'can only call blocking when on Tokio runtime', src/libcore/option.rs:1190:5

main.rs:

#[tokio::main]
async fn main() {
    tokio::task::block_in_place(|| {});
}

Cargo.toml:

[package]
name = "tokio-fs-test"
version = "0.1.0"
authors = ["Nicholas Bishop <nbishop@neverware.com>"]
edition = "2018"

[dependencies]
tokio = { version = "0.2.4", features = ["full"] }

[carllerche]

@nicholasbishop wrap that w/ a spawn(....).await

There is still some more work to do on this front.

[carllerche]

right now you can't use block_in_place in the "Main" task, but that is due to some missing internal wiring.

[nicholasbishop]

Confirmed that using spawn fixed the error. Thanks for the help :)

[lovasoa]

Could this be added to the documentation of block_in_place ?
I just spent a long time trying to figure out where this thread 'main' panicked at 'can only call blocking when on Tokio runtime' came from...

[Darksonn]

There have been a bunch of PRs making block_in_place usable in more places. I'll close this for now. Feel free to open an issue if block_in_place is still not usable in main on the threaded executor.

[lnicola]

@Darksonn it doesn't look like this was actually fixed. block_in_place might be easier to use now, but it's not obvious that you'll get bad performance if you use tokio::fs instead of std::fs.

[Darksonn]

Right, I've been meaning to document this better for a while. I opened an issue about it. We can continue the discussion there.