Performance of download

[m0ppers]

I am not sure if I am doing something wrong but the download speed is way slower than it could be. I am trying to fetch a 1GiB file from my local vm as a testcase. The vm is just a freshly setup debian 12 with only openssh installed.

This is what I am doing:

use async_trait::async_trait;
use log::{info, LevelFilter};
use russh::*;
use russh_keys::*;
use russh_sftp::client::SftpSession;
use std::sync::Arc;
use tokio::io::{BufReader, BufWriter};

struct Client;

#[async_trait]
impl client::Handler for Client {
    type Error = anyhow::Error;

    async fn check_server_key(
        &mut self,
        server_public_key: &key::PublicKey,
    ) -> Result<bool, Self::Error> {
        info!("check_server_key: {:?}", server_public_key);
        Ok(true)
    }
}

#[tokio::main]
async fn main() {
    env_logger::builder().filter_level(LevelFilter::Warn).init();

    let file_size = 1024 * 1024 * 1024;

    let config = russh::client::Config {
        limits: Limits::default(),
        window_size: file_size as u32,
        ..Default::default()
    };
    let mut session = russh::client::connect(Arc::new(config), ("192.168.122.242", 22), Client)
        .await
        .unwrap();

    if session.authenticate_password("mop", "mop").await.unwrap() {
        let channel = session.channel_open_session().await.unwrap();
        channel.request_subsystem(false, "sftp").await.unwrap();
        let sftp = SftpSession::new(channel.into_stream()).await.unwrap();

        // interaction with i/o
        let start = std::time::Instant::now();
        let filename = "test";
        let file = sftp.open(filename).await.unwrap();

        let mut buf = Vec::with_capacity(file_size);
        let mut reader = BufReader::with_capacity(file_size, file);
        // let mut writer = BufWriter::with_capacity(1024 * 1024 * 100, buf);
        // let mut reader = BufReader::new(file);
        let mut writer = BufWriter::new(&mut buf);

        tokio::io::copy_buf(&mut reader, &mut writer).await.unwrap();

        println!("read in {:?}", start.elapsed());
    }
}

After tweaking the values a bit I get roughly 60-70 MBps:

[mop@udoo-juergens russh-sftp-client]$ target/release/russh-sftp-client 
read in 15.670531058s

without doing anything I get only 10 MBps :face_with_spiral_eyes: :

read in 100.284998668s

A quick test with the sftp command line:

[mop@udoo-juergens russh-sftp-client]$ sftp mop@192.168.122.242
Connected to 192.168.122.242.
sftp> get test
Fetching /home/mop/test to test
test                                                                                         100% 1024MB 270.1MB/s   00:03    
sftp> 

Is this the expected performance? Or did I do something wrong? :thinking:

I also did a quick cross check using a go library and this one is very close to what the sftp command line is doing:

package main

import (
    "bufio"
    "fmt"
    "log"
    "os"
    "time"

    "github.com/pkg/sftp"
    "golang.org/x/crypto/ssh"
)

func main() {
    start := time.Now()
    // var hostKey ssh.PublicKey
    config := &ssh.ClientConfig{
        User: "mop",
        Auth: []ssh.AuthMethod{
            ssh.Password("mop"),
        },
        HostKeyCallback: ssh.InsecureIgnoreHostKey(),
    }
    sclient, err := ssh.Dial("tcp", "192.168.122.242:22", config)
    if err != nil {
        log.Fatal("Failed to dial: ", err)
    }
    defer sclient.Close()

    // open an SFTP session over an existing ssh connection.
    client, err := sftp.NewClient(sclient)
    if err != nil {
        log.Fatal(err)
    }
    defer client.Close()

    f, err := client.Open("test")
    if err != nil {
        log.Fatal(err)
    }

    localFile, err := os.Create("test")
    if err != nil {
        log.Fatal(err)
    }
    defer localFile.Close()

    writer := bufio.NewWriter(localFile)

    f.WriteTo(writer)
    f.Close()

    writer.Flush()
    fmt.Printf("File downloaded %v\n", time.Since(start))
}

[AspectUnk]

Your example runs in about 40-50 seconds for me, which is still pretty slow. I noticed that after sending the packet, it takes anywhere from 2-4ms to get the first response data, but sometimes it spikes up to 42ms, which seems suspiciously slow. I'll dive into more debugging as soon as I get some more time.

[m0ppers]

I digged a bit deeper and can reproduce that it sometime takes longer than 40ms to read(). The 40ms are happening whenever it renegotiates the window. By setting the window_size to 0xfffffff I was able to come around that. Still: I am stuck at 70MB/s whereas it should be 200MB+