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 😵‍💫 :

read in 100.284998668s

A quick test with the sftp command line:

[mop@udoo-juergens russh-sftp-client]$ sftp [email protected]
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? 🤔

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+

[AspectUnk]

While trying to reproduce the issue, I noticed that it is no longer relevant and seems to have been resolved in Eugeny/russh#412. At this point, the download speed in your example is about 54 MBps, which is roughly the same as the WinSCP client speed of around 56.8 MBps