Low-latency communication

[dennybritz]

I've been investigating async for processing that requires low end-to-end latency. I wrote a simple benchmark that measures the average time between channel sends and receives:

use std::time::Instant;

#[tokio::main(flavor = "current_thread")]
async fn main() {
    let n = 50_000;
    let (tx, mut rx) = tokio::sync::mpsc::channel::<Instant>(1);

    let read = tokio::spawn(async move {
        let mut total: u128 = 0;
        while let Some(ts) = rx.recv().await {
            total = total + ts.elapsed().as_nanos();
        }
        let mean = std::time::Duration::from_nanos((total / n) as u64);
        println!("{:?}", mean);
    });

    let write = tokio::spawn(async move {
        for _ in 0..n {
            tx.send(Instant::now()).await.unwrap();
            tokio::task::yield_now().await;
            // tokio::time::sleep(std::time::Duration::from_millis(1)).await;
        }
    });

    futures::future::join(read, write).await;    
}

The output of this is 495ns on my machine. This is great, just what I was looking for. However, the times increase by 10-15x when I uncomment the sleep line in the code above. And by more if I consider the 99th percentile instead of the average. It doesn't need to be sleep - I get the same behavior when messages arrive at a slower pace coming from IO for example. The sleep is just there to emulate this.

Now, it kind of makes sense to me that idling between channels sends would result in the CPU doing other stuff and overwriting data in caches, etc. That would make it slower, but not 10-15x slower. So I'm curious, what exactly is happening here that leads to this latency increase?

[stsydow]

You can do profiling for further insights:

$ perf stat -r3 -e syscalls:sys_enter_futex,syscalls:sys_enter_read,syscalls:sys_enter_sched_yield,syscalls:sys_enter_epoll_pwait,context-switches,cycles:k,cycles:u,instructions,task-clock ./target/release/channel_latency > without_sleep

with yield:

Performance counter stats for './target/release/channel_latency' (3 runs):

             0      syscalls:sys_enter_futex  #    0.000 K/sec                  
             7      syscalls:sys_enter_read   #    0.050 K/sec                  
         4,686      syscalls:sys_enter_sched_yield #    0.034 M/sec                  
         1,640      syscalls:sys_enter_epoll_pwait #    0.012 M/sec                  
             2      context-switches          #    0.012 K/sec                    ( +- 40.00% )
    24,408,977      cycles:k                  #    0.175 GHz                      ( +-  1.80% )
   254,504,889      cycles:u                  #    1.825 GHz                      ( +-  0.92% )
    82,507,963      instructions                                                  ( +-  0.03% )
        139.48 msec task-clock                #    0.987 CPUs utilized            ( +-  0.83% )

       0.14135 +- 0.00117 seconds time elapsed  ( +-  0.83% )

with sleep:

Performance counter stats for './target/release/channel_latency' (3 runs):

             0      syscalls:sys_enter_futex  #    0.000 K/sec                  
             7      syscalls:sys_enter_read   #    0.000 K/sec                  
         4,686      syscalls:sys_enter_sched_yield #    0.099 K/sec                  
    20,483,557      syscalls:sys_enter_epoll_pwait #    0.433 M/sec                    ( +-  0.90% )
        50,047      context-switches          #    0.001 M/sec                    ( +-  0.03% )
29,519,202,257      cycles:k                  #    0.624 GHz                      ( +-  0.99% )
64,819,043,583      cycles:u                  #    1.370 GHz                      ( +-  0.44% )
43,593,902,261      instructions                                                  ( +-  0.89% )
     47,303.81 msec task-clock                #    0.473 CPUs utilized            ( +-  0.01% )

    100.002742 +- 0.000107 seconds time elapsed  ( +-  0.00% )

without both: (only tx.send(Instant::now()).await.unwrap())

Performance counter stats for './target/release/channel_latency' (3 runs):

             0      syscalls:sys_enter_futex  #    0.000 K/sec                  
             7      syscalls:sys_enter_read   #    0.046 K/sec                  
         4,686      syscalls:sys_enter_sched_yield #    0.031 M/sec                  
         1,640      syscalls:sys_enter_epoll_pwait #    0.011 M/sec                  
             0      context-switches          #    0.002 K/sec                    ( +-100.00% )
    13,934,271      cycles:k                  #    0.092 GHz                      ( +-  0.48% )
   287,523,894      cycles:u                  #    1.907 GHz                      ( +-  0.06% )
    92,942,479      instructions                                                  ( +-  0.07% )
        150.73 msec task-clock                #    0.996 CPUs utilized            ( +-  0.08% )

      0.151351 +- 0.000107 seconds time elapsed  ( +-  0.07% )

[dennybritz]

Thanks a lot! I'm not super familiar with the low-level details and syscalls, but from what it looks like the culprit are the many process context switches? And the only way to avoid that would be to spin in a loop as opposed to using something that uses epoll such as blocking sockets or sleep? Does that sound right?

[stsydow]

Basicly you want to avoid systemcalls as far as possible, but time keeping is done by the OS and it makes no sense to burn cpu cycles for waiting longer than a few microseconds.

If your benchmarking the channel don't use sleep(). It is way to expensive. And why would you wait so long?
More interesting is what happens with a multi-thread runtime where the channel needs to synchronize.