Issues with Windows timeout behavior

[mlsvrts]

So I am having some issues with performance when reading interrupted byte streams from the serial port. Consider this example:

Cargo.toml

[package]
name = "async-serial-test"
version = "0.1.0"
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]
tokio = { version = "1", features = ["io-util", "macros", "rt-multi-thread"]}
tokio-serial = "5.4.1"

main.rs

use std::time;
use tokio::{task, io::{self, AsyncReadExt, AsyncWriteExt}};
use tokio_serial::SerialPortBuilderExt;

#[tokio::main]
async fn main() {
    let mut args = std::env::args();
    let path = args.nth(1).expect("specify the serial port to connect to!");
    let bytes = args.next()
        .map_or(Ok(1024), |s| usize::from_str_radix(s.as_str(), 10))
        .expect("expected a number of bytes as the second argument");

    let port = tokio_serial::new(&path, 115200)
        .open_native_async()
        .expect("failed to open the system serial port");

    let (mut reader, mut writer) = io::split(port);
    
    let message = vec![13u8; bytes];
    let expected = message.len();

    let read = task::spawn(async move {
        let mut buf = [0u8; 1];

        let mut total = 0;
        let mut timestamp;
        let now = time::Instant::now();
        loop {
            match reader.read(&mut buf).await {
                Ok(n) => {
                    total += n;
                    timestamp = now.elapsed().as_secs_f32();
                    // println!("[{}] read {} bytes: {:?}", timestamp, n, &buf[..n])
                    if total >= expected { break; }
                },
                Err(e) => {
                    println!("serial read encountered an error: {:?}", e);
                    panic!("failed to read any data from the io device");
                }
            }
        }

        println!("read {} bytes in {}s --> {}b/s", total, timestamp, total as f32 / timestamp);
    });

    writer.write(&message).await
        .expect("failed to write to the serial port");

    println!("waiting for read to complete...");
    
    tokio::try_join!(read)
        .expect("failed to join read task");
}

If we run this program we can see the following:

C:\>.\build\async-serial-test.exe COM1 8192
waiting for read to complete...
read 8192 bytes in 0.7650555s --> 10707.72b/s

C:\>.\build\async-serial-test.exe COM1 8191
waiting for read to complete...
read 8191 bytes in 0.78255415s --> 10467.007b/s

It takes longer (by ~17ms (!)) to write/read one byte less of data! If we examine the syscalls, I think we can find the culprit:

The serial library is issuing read requests for 4096 bytes, which of course time out when only 4095 bytes are available -- the problem is that this timeout should* be 1ms, but in practice appears to be quite long.

*based on: https://github.com/berkowski/mio-serial/blob/8cb54a5667e66632016db5ee5b9977c67713ceec/src/lib.rs#L810

So this leaves me with two questions:

1. Do you know how/why COMMTIMEOUTS seems to be basically ignored? I have done some searching, and it seems like the answer to this question is that no-one actually knows what this windows code really does.
2. How is the read-request size set? Can I use an different API to poll for smaller chunks of bytes? PuTTy polls for 1-byte reads, for instance; this way the pending read is returned as soon as there is more data.

[mlsvrts]

After some review, I have determined that the read size is set by the NamedPipe from mio. See: https://github.com/tokio-rs/mio/blob/c9e33691034be4df491fed7b24b5eeb4d20f8d7d/src/sys/windows/named_pipe.rs#L805

And behold, if I modify this to .get(1):

C:\>.\build\async-serial-test.exe COM1 8192
waiting for read to complete...
read 8192 bytes in 0.76019627s --> 10776.164b/s

C:\>.\build\async-serial-test.exe COM1 8191
waiting for read to complete...
read 8191 bytes in 0.761495s --> 10756.473b/s

The discrepency between 8192 and 8191 bytes is now well within measurement error. I can't see any obvious way to modify this value without changing mio, so this solution may need some workshopping...

[estokes]

Thanks for the detailed report. This is ... awful.

[mlsvrts]

@estokes No problem, maybe this will help some other poor soul someday.

To that end, I have one additional note for anyone (like me) who is attempting to implement a Decoder on a Windows serialport.

Because mio-serial sets the commtimeouts as a 1ms interbyte timeout, if you reach a gap in your data stream, the (zero data) timeout will cause the Stream implementation to return None. This is because the Windows ReadFile API does not produce timeout errors, so this is indistinguishable from a read that returns no data to the Stream.

If you don't want your decoder to shutdown on timeouts, you could disable read timeouts entirely:

ReadIntervalTimeout: 0,

But if you do this reads will not complete, until they have read enough data to fill the buffer requested by NamedPipe, so it's a bad idea unles you've set the read request size to one byte. Instead, you could also just:

loop { while let Some(item) = stream.next().await {
    // code goes here 
} }

The Framed stream will return Some(Err(...)) on any errors produced by the read request, so it should be safe to restart this loop if you check for these errors.

[vadixidav]

This is still an issue. For those who need a solution, I just updated the hack to get windows serial running smoothly to tokio 1.24.1. You will need to patch your mio and tokio with my branches:

[patch.crates-io]
mio = { git = 'https://github.com/vadixidav/mio.git', branch = 'issue#1582_named_pipe_set_buffer_size' }
tokio = { git = 'https://github.com/vadixidav/tokio.git', branch = 'mio#1608_hack' }

If you depend on this, please upload the branches elsewhere. I may update them to a newer version of tokio and mio.

[DanielJoyce]

Windows has weird serial port behavior, workarounds are discussed for the other serialport-rs crate. With some judicious settings you can make windows behave more sanely.

[larsch]

I'm seeing what might be related, also on Windows: All reads take a minimum of 27-30 milliseconds to complete, no matter how fast the serial device is. This severely impacts my performance to the point of being unusable since I need to send a reply quickly to maintain throughput on my device (USB serial, with no actual UART, so 12 MBps USB speeds are theoretically possible).

[vadixidav]

I'm seeing what might be related, also on Windows: All reads take a minimum of 27-30 milliseconds to complete, no matter how fast the serial device is. This severely impacts my performance to the point of being unusable since I need to send a reply quickly to maintain throughput on my device (USB serial, with no actual UART, so 12 MBps USB speeds are theoretically possible).

I believe that is a different issue. This issue is that until the buffer is filled, Windows will not send you the data for a very long time, which I have found to be on the order of half a second. It is possible you are seeing the same issue but your timeout is smaller. Regardless, the system I am working with cannot operate without this hack, so I am hoping for a solution. My vote is still to just make the windows buffer size 1 through the added API. As it stands, Windows is broken, so I believe even a hacky solution is better than being broken.

[larsch]

I believe that is a different issue. This issue is that until the buffer is filled, Windows will not send you the data for a very long time,

I have filed PRs to the issue of read calls not returning until buffer filled on serialport/serialport-rs#79 and berkowski/mio-serial#38.

It may also address this issue.