SFTP performance

[lochnar187]

I am seeing some performance issues and would like to ask others to take my test code and see if they have the same problem. Mostly, this is because I am running this against an SFTP server that I don't control or have any knowledge about, it's "black box" to me. So I want to make sure it's not that.

After noticing I wasn't getting the speeds I expected (sometimes as little as half) I wrote some code that gives a head to head comparison of speeds between SSH.NET and WinSCP. I used NuGet to get the latest versions of both SSH.NET and WinSCP. Testing file is an 834KB file.

Using VS 2015
Code build is targeted on .NET Framework 4.5.2
OS is Windows 10 (dev machine) and Windows Server 2012 R2 (test machine)

SSH.NET version, 2016.0.0
WinSCP version, 5.9.2

SFTP server reports it is: SSH-2.0-WS_FTP-SSH_7.6.3

Test Code:

using Renci.SshNet;
using System;
using System.Diagnostics;
using System.IO;
using WinSCP;

namespace SFTP_Compare {
    class Program {
        static string strServer     = "xxxx";
        static string strUser       = "xxxx";
        static string strPass       = "xxxx";
        static string strHostKey    = "ssh-rsa 1024 xxxxxx";
        static string strRmPath     = "/home/";
        static string strLcPath     = "C:\\Data\\";
        static string strFile       = "test_file.xyz";
        static int    intPort       = 22;
        static void TestWinSCP(int pintLoops) {
            long    lngByteKnt  = 0;
            double  dblCreated, dblConnected, dblOpenStream, dblDownloaded, dblEndTime;
            double  dblKBKntTotal = 0.0, dblCreatedTotal = 0.0, dblConnectedTotal = 0.0, dblOpenStreamTotal = 0.0, dblDownloadedTotal = 0.0, dblEndTimeTotal = 0.0;
            Stopwatch swTimer = new Stopwatch();

            Console.WriteLine();
            Console.WriteLine("WinSCP download test, {0} iteration(s).", pintLoops);
            Console.WriteLine("___________________________________________________________________");
            Console.WriteLine("|  Run  |  Client Cr |  Connection  |    Download    |   Delete   |");

            for (int i = 0; i < pintLoops; i++) {
                try {
                    swTimer.Start();
                    SessionOptions soptSettings = new SessionOptions();
                    soptSettings.Protocol = Protocol.Sftp;
                    soptSettings.HostName = strServer;
                    soptSettings.UserName = strUser;
                    soptSettings.Password = strPass;
                    soptSettings.SshHostKeyFingerprint = strHostKey;
                    using (WinSCP.Session sesConnection = new WinSCP.Session()) {
                        swTimer.Stop();
                        dblCreated = swTimer.Elapsed.TotalMilliseconds;
                        swTimer.Restart();
                        sesConnection.Open(soptSettings);
                        swTimer.Stop();
                        dblConnected = swTimer.Elapsed.TotalMilliseconds;
                        swTimer.Restart();
                        dblOpenStream = 0;
                        TransferOptions toptStreamSettings = new TransferOptions();
                        toptStreamSettings.TransferMode = TransferMode.Binary;
                        sesConnection.GetFiles(strRmPath + strFile, strLcPath + strFile, false, toptStreamSettings);
                        swTimer.Stop();
                        dblDownloaded = swTimer.Elapsed.TotalMilliseconds;
                        FileInfo fiFile = new FileInfo(strLcPath + strFile);
                        lngByteKnt = fiFile.Length;
                        swTimer.Restart();
                    }
                    File.Delete(strLcPath + strFile); // Delete local copy for next run...WRG
                    swTimer.Stop();
                    dblEndTime = swTimer.Elapsed.TotalMilliseconds;

                    // Output test results...WRG
                    Console.WriteLine("|{0,4}   |{1,8:N1} ms |{2,10:N1} ms |{3,12:N1} ms |{4,8:N1} ms |", i + 1, dblCreated, dblConnected, dblDownloaded, dblEndTime);

                    // Save totals for later...WRG
                    dblKBKntTotal += (lngByteKnt / 1024);
                    dblCreatedTotal += dblCreated;
                    dblConnectedTotal += dblConnected;
                    dblOpenStreamTotal += dblOpenStream;
                    dblDownloadedTotal += (dblDownloaded);
                    dblEndTimeTotal += dblEndTime;

                } catch (Exception ex) {
                    Console.WriteLine(" *** Error on run {0}, Message: {1}", i + 1, ex.Message);
                }
            }
            Console.WriteLine("|=======|============|==============|================|============|");
            Console.WriteLine("|  avg  |{0,8:N1} ms |{1,10:N1} ms |{2,12:N1} ms |{3,8:N1} ms |", (dblCreatedTotal / pintLoops), (dblConnectedTotal / pintLoops), (dblDownloadedTotal / pintLoops), (dblEndTimeTotal / pintLoops));
            Console.WriteLine("|_______|____________|______________|________________|____________|");
            Console.WriteLine(" *** Average download speed for {0:N0} bytes: {1,5:N2} KB/s", (dblKBKntTotal * 1024), (dblKBKntTotal / (dblDownloadedTotal / 1000)));
            Console.WriteLine();
        }
        static void TestSSHNET(int pintLoops) {
            long    lngByteKnt  = 0;
            double  dblCreated, dblConnected, dblOpenStream, dblDownloaded, dblEndTime;
            double  dblKBKntTotal = 0.0, dblCreatedTotal = 0.0, dblConnectedTotal = 0.0, dblOpenStreamTotal = 0.0, dblDownloadedTotal = 0.0, dblEndTimeTotal = 0.0;
            Stopwatch swTimer = new Stopwatch();

            Console.WriteLine();
            Console.WriteLine("SSH.NET download test, {0} iteration(s).", pintLoops);
            Console.WriteLine("___________________________________________________________________");
            Console.WriteLine("|  Run  |  Client Cr |  Connection  |    Download    |   Delete   |");

            for (int i = 0; i < pintLoops; i++) {
                try {
                    swTimer.Start();
                    using (SftpClient sftpClient = new SftpClient(strServer, intPort, strUser, strPass)) {
                        swTimer.Stop();
                        dblCreated = swTimer.Elapsed.TotalMilliseconds;
                        swTimer.Restart();
                        sftpClient.Connect();
                        swTimer.Stop();
                        dblConnected = swTimer.Elapsed.TotalMilliseconds;
                        swTimer.Restart();
                        using (Stream sFile = File.Open(strLcPath + strFile, FileMode.Create, FileAccess.Write)) {
                            dblOpenStream = 0;
                            //swTimer.Stop();
                            //dblOpenStream = swTimer.Elapsed.TotalMilliseconds;
                            //swTimer.Restart();
                            sftpClient.DownloadFile(strRmPath + strFile, sFile);
                            swTimer.Stop();
                            dblDownloaded = swTimer.Elapsed.TotalMilliseconds;
                            lngByteKnt = sFile.Length;
                            swTimer.Restart();
                        }
                    }
                    File.Delete(strLcPath + strFile); // Delete local copy for next run...WRG
                    swTimer.Stop();
                    dblEndTime = swTimer.Elapsed.TotalMilliseconds;

                    // Output test results...WRG
                    Console.WriteLine("|{0,4}   |{1,8:N1} ms |{2,10:N1} ms |{3,12:N1} ms |{4,8:N1} ms |", i+1, dblCreated, dblConnected, dblDownloaded, dblEndTime);

                    // Save totals for later...WRG
                    dblKBKntTotal += (lngByteKnt/1024);
                    dblCreatedTotal += dblCreated;
                    dblConnectedTotal += dblConnected;
                    dblOpenStreamTotal += dblOpenStream;
                    dblDownloadedTotal += (dblDownloaded);
                    dblEndTimeTotal += dblEndTime;

                } catch (Exception ex) {
                    Console.WriteLine(" *** Error on run {0}, Message: {1}", i+1, ex.Message);
                }
            }
            Console.WriteLine("|=======|============|==============|================|============|");
            Console.WriteLine("|  avg  |{0,8:N1} ms |{1,10:N1} ms |{2,12:N1} ms |{3,8:N1} ms |", (dblCreatedTotal / pintLoops), (dblConnectedTotal / pintLoops), (dblDownloadedTotal / pintLoops), (dblEndTimeTotal / pintLoops));
            Console.WriteLine("|_______|____________|______________|________________|____________|");
            Console.WriteLine(" *** Average download speed for {0:N0} bytes: {1,5:N2} KB/s", (dblKBKntTotal * 1024), (dblKBKntTotal / (dblDownloadedTotal / 1000)));
            Console.WriteLine();
        }

        static void Main(string[] args) {
            TestWinSCP(50);
            TestSSHNET(50);
        }
    }
}

Output from command prompt session on test machine:

Microsoft Windows [Version 6.3.9600]
(c) 2013 Microsoft Corporation. All rights reserved.

C:\Windows\system32>cd C:\Data

C:\Data>dir
 Volume in drive C has no label.
 Volume Serial Number is E6AE-D23F

 Directory of C:\Data

10/11/2016  01:03 PM    <DIR>          .
10/11/2016  01:03 PM    <DIR>          ..
10/06/2016  07:21 PM           408,064 Renci.SshNet.dll
10/06/2016  07:21 PM           961,463 Renci.SshNet.xml
10/11/2016  01:02 PM             9,216 SFTP_Compare.exe
10/06/2016  07:18 PM               189 SFTP_Compare.exe.config
10/11/2016  01:02 PM            15,872 SFTP_Compare.pdb
10/10/2016  03:03 PM            22,696 SFTP_Compare.vshost.exe
10/06/2016  07:18 PM               189 SFTP_Compare.vshost.exe.config
07/10/2015  07:01 AM               490 SFTP_Compare.vshost.exe.manifest
10/06/2016  07:22 PM        18,886,048 WinSCP.exe
10/08/2016  02:48 PM                75 winscp.ini
10/06/2016  07:22 PM           149,584 WinSCPnet.dll
              11 File(s)     20,453,886 bytes
               2 Dir(s)  16,536,723,456 bytes free

C:\Data>sftp_compare

WinSCP download test, 50 iteration(s).
___________________________________________________________________
|  Run  |  Client Cr |  Connection  |    Download    |   Delete   |
|   1   |     4.2 ms |   1,797.8 ms |       781.9 ms |   110.5 ms |
|   2   |   110.6 ms |   1,778.7 ms |       843.9 ms |   110.3 ms |
|   3   |   110.4 ms |   1,779.8 ms |       843.7 ms |   110.4 ms |
|   4   |   110.4 ms |   1,779.9 ms |       843.8 ms |   110.4 ms |
|   5   |   110.4 ms |   1,779.9 ms |       843.8 ms |   110.5 ms |
|   6   |   110.5 ms |   1,779.8 ms |       843.7 ms |   110.3 ms |
|   7   |   110.4 ms |   1,780.0 ms |       843.8 ms |   110.3 ms |
|   8   |   110.3 ms |   2,592.7 ms |       843.8 ms |   110.6 ms |
|   9   |   110.7 ms |   2,582.1 ms |       843.6 ms |   110.2 ms |
|  10   |   110.3 ms |   1,782.1 ms |     1,656.3 ms |   110.6 ms |
|  11   |   110.7 ms |   1,779.4 ms |       843.9 ms |   110.4 ms |
|  12   |   110.4 ms |   2,592.2 ms |       843.8 ms |   110.5 ms |
|  13   |   110.6 ms |   1,779.7 ms |       843.9 ms |   110.6 ms |
|  14   |   110.7 ms |   1,779.4 ms |     1,656.4 ms |   110.2 ms |
|  15   |   110.3 ms |   2,592.3 ms |       843.7 ms |   110.6 ms |
|  16   |   110.7 ms |   2,592.1 ms |       843.9 ms |   110.2 ms |
|  17   |   110.3 ms |   1,779.9 ms |       843.8 ms |   110.6 ms |
|  18   |   110.7 ms |   1,779.7 ms |       843.8 ms |   110.6 ms |
|  19   |   110.7 ms |   2,591.9 ms |       843.9 ms |   110.4 ms |
|  20   |   110.5 ms |   1,779.5 ms |       846.6 ms |   110.5 ms |
|  21   |   110.5 ms |   2,593.7 ms |       844.8 ms |   110.2 ms |
|  22   |   110.3 ms |   1,780.0 ms |       843.7 ms |   113.8 ms |
|  23   |   113.9 ms |   2,590.6 ms |       843.8 ms |   110.5 ms |
|  24   |   110.6 ms |   2,582.5 ms |       843.7 ms |   110.6 ms |
|  25   |   110.7 ms |   1,780.0 ms |       843.8 ms |   110.6 ms |
|  26   |   110.6 ms |   1,779.7 ms |       843.8 ms |   110.4 ms |
|  27   |   110.5 ms |   2,592.1 ms |       843.9 ms |   110.2 ms |
|  28   |   110.2 ms |   1,780.8 ms |     1,656.3 ms |   110.3 ms |
|  29   |   110.4 ms |   1,779.8 ms |       843.9 ms |   110.5 ms |
|  30   |   110.5 ms |   1,779.8 ms |       843.7 ms |   110.6 ms |
|  31   |   110.7 ms |   1,779.6 ms |       843.9 ms |   110.7 ms |
|  32   |   110.8 ms |   1,779.1 ms |       843.9 ms |   110.5 ms |
|  33   |   110.6 ms |   2,592.0 ms |       843.7 ms |   111.1 ms |
|  34   |   111.2 ms |   2,592.5 ms |       843.8 ms |   110.0 ms |
|  35   |   110.1 ms |   1,781.4 ms |       843.6 ms |   110.4 ms |
|  36   |   110.5 ms |   2,592.9 ms |       843.8 ms |   110.2 ms |
|  37   |   110.3 ms |   1,780.0 ms |       843.7 ms |   110.2 ms |
|  38   |   110.3 ms |   1,776.1 ms |       843.7 ms |   110.6 ms |
|  39   |   110.7 ms |   2,592.2 ms |       843.7 ms |   110.3 ms |
|  40   |   110.4 ms |   1,780.0 ms |       843.7 ms |   110.4 ms |
|  41   |   110.4 ms |   2,592.9 ms |       843.8 ms |   110.3 ms |
|  42   |   110.3 ms |   1,780.4 ms |       843.9 ms |   110.4 ms |
|  43   |   110.5 ms |   2,592.2 ms |       843.8 ms |   110.5 ms |
|  44   |   110.6 ms |   2,592.3 ms |       843.7 ms |   102.5 ms |
|  45   |   102.6 ms |   1,779.5 ms |       843.7 ms |   110.3 ms |
|  46   |   110.4 ms |   2,593.1 ms |     1,657.7 ms |   110.3 ms |
|  47   |   110.4 ms |   1,779.6 ms |       843.8 ms |   110.5 ms |
|  48   |   110.6 ms |   2,582.8 ms |       843.8 ms |   110.1 ms |
|  49   |   110.2 ms |   1,779.6 ms |       843.7 ms |   110.3 ms |
|  50   |   110.4 ms |   1,781.4 ms |       843.8 ms |   110.5 ms |
|=======|============|==============|================|============|
|  avg  |   108.3 ms |   2,088.4 ms |       907.7 ms |   110.3 ms |
|_______|____________|______________|________________|____________|
 *** Average download speed for 42,700,800 bytes: 918.86 KB/s


SSH.NET download test, 50 iteration(s).
___________________________________________________________________
|  Run  |  Client Cr |  Connection  |    Download    |   Delete   |
|   1   |    11.3 ms |     974.3 ms |     1,337.5 ms |   190.6 ms |
|   2   |   190.6 ms |     815.4 ms |     1,323.7 ms |   195.5 ms |
|   3   |   195.5 ms |   1,365.0 ms |     1,452.2 ms |   190.0 ms |
|   4   |   190.0 ms |   1,577.7 ms |     1,516.7 ms |   202.2 ms |
|   5   |   202.3 ms |   1,197.2 ms |     1,562.5 ms |   192.6 ms |
|   6   |   192.7 ms |   1,194.1 ms |     1,584.5 ms |   189.3 ms |
|   7   |   189.3 ms |   1,311.7 ms |     1,609.4 ms |   198.8 ms |
|   8   |   198.8 ms |   1,477.7 ms |     1,427.2 ms |   188.1 ms |
|   9   |   188.2 ms |   1,417.4 ms |     1,561.7 ms |   201.3 ms |
|  10   |   201.3 ms |   1,401.8 ms |     1,926.7 ms |   194.3 ms |
|  11   |   194.3 ms |   1,401.4 ms |     1,599.1 ms |   190.2 ms |
|  12   |   190.3 ms |   1,528.9 ms |     1,607.8 ms |   197.8 ms |
|  13   |   197.9 ms |   1,338.8 ms |     1,770.6 ms |   196.8 ms |
|  14   |   196.9 ms |   1,833.7 ms |     1,683.3 ms |   201.9 ms |
|  15   |   201.9 ms |   1,414.5 ms |     1,405.0 ms |   195.4 ms |
|  16   |   195.4 ms |   1,197.0 ms |     1,465.8 ms |   216.8 ms |
|  17   |   216.9 ms |     854.8 ms |     1,282.3 ms |   192.2 ms |
|  18   |   192.2 ms |   1,121.3 ms |     1,356.2 ms |   200.7 ms |
|  19   |   200.7 ms |   1,166.9 ms |     1,321.3 ms |   193.4 ms |
|  20   |   193.4 ms |   1,147.5 ms |     1,341.7 ms |   202.1 ms |
|  21   |   202.1 ms |   1,165.9 ms |     1,549.1 ms |   202.5 ms |
|  22   |   202.5 ms |   1,157.9 ms |     1,469.9 ms |   202.1 ms |
|  23   |   202.2 ms |   1,420.7 ms |     1,295.2 ms |   189.1 ms |
|  24   |   189.2 ms |   1,191.0 ms |     1,428.3 ms |   193.2 ms |
|  25   |   193.2 ms |   1,251.3 ms |     2,123.6 ms |   190.8 ms |
|  26   |   190.8 ms |   2,066.9 ms |     1,852.7 ms |   190.1 ms |
|  27   |   190.1 ms |   1,295.0 ms |     1,322.2 ms |   198.5 ms |
|  28   |   198.5 ms |   1,256.5 ms |     1,364.1 ms |   190.4 ms |
|  29   |   190.4 ms |   1,338.1 ms |     1,509.6 ms |   188.2 ms |
|  30   |   188.3 ms |     863.8 ms |     1,268.3 ms |   200.8 ms |
|  31   |   200.8 ms |     830.0 ms |     1,263.6 ms |   199.9 ms |
|  32   |   199.9 ms |   1,245.4 ms |     1,709.0 ms |   199.5 ms |
|  33   |   199.5 ms |   1,316.6 ms |     1,409.2 ms |   200.2 ms |
|  34   |   200.3 ms |   1,367.3 ms |     1,335.6 ms |   201.4 ms |
|  35   |   201.4 ms |   1,309.9 ms |     1,434.1 ms |   195.3 ms |
|  36   |   195.3 ms |     855.0 ms |     1,299.7 ms |   188.2 ms |
|  37   |   188.2 ms |   1,400.1 ms |     1,395.0 ms |   188.3 ms |
|  38   |   188.3 ms |   1,339.3 ms |     1,466.6 ms |   199.9 ms |
|  39   |   199.9 ms |   1,604.9 ms |     1,511.3 ms |   256.2 ms |
|  40   |   256.3 ms |   1,414.4 ms |     1,353.6 ms |   186.9 ms |
|  41   |   186.9 ms |   1,393.3 ms |     1,414.8 ms |   196.7 ms |
|  42   |   196.7 ms |     889.2 ms |     1,269.1 ms |   196.9 ms |
|  43   |   197.0 ms |     809.1 ms |     1,397.1 ms |   199.6 ms |
|  44   |   199.6 ms |   1,305.2 ms |     1,567.5 ms |   188.3 ms |
|  45   |   188.3 ms |     882.4 ms |     1,376.4 ms |   201.8 ms |
|  46   |   201.9 ms |   1,276.5 ms |     1,633.0 ms |   218.6 ms |
|  47   |   218.7 ms |   1,211.7 ms |     1,462.9 ms |   197.9 ms |
|  48   |   197.9 ms |     783.3 ms |     1,288.4 ms |   193.7 ms |
|  49   |   193.8 ms |   1,333.6 ms |     1,439.8 ms |   201.3 ms |
|  50   |   201.3 ms |   1,171.2 ms |     1,374.2 ms |   191.5 ms |
|=======|============|==============|================|============|
|  avg  |   194.0 ms |   1,249.7 ms |     1,474.4 ms |   197.6 ms |
|_______|____________|______________|________________|____________|
 *** Average download speed for 42,700,800 bytes: 565.66 KB/s


C:\Data>

I'd welcome any suggestions to improve performance.

Thanks

[drieseng]

Below you find the results I get with a 843 Kb file hosted on a VM (OpenSSH_6.6.1p1).
This is with SSH.NET built from the develop branch.

WinSCP download test, 50 iteration(s).

___________________________________________________________________
|  Run  |  Client Cr |  Connection  |    Download    |   Delete   |
|   1   |     3,4 ms |   1 422,9 ms |        56,0 ms |   101,7 ms |
|   2   |   101,7 ms |     910,2 ms |        50,9 ms |   101,2 ms |
|   3   |   101,3 ms |     910,2 ms |        50,9 ms |   101,7 ms |
|   4   |   101,8 ms |     913,8 ms |        50,8 ms |   101,3 ms |
|   5   |   101,3 ms |     912,3 ms |        50,9 ms |   101,2 ms |
|   6   |   101,2 ms |     909,3 ms |        50,9 ms |   102,6 ms |
|   7   |   102,7 ms |     912,3 ms |        50,8 ms |   102,1 ms |
|   8   |   102,2 ms |     914,6 ms |        51,8 ms |   102,8 ms |
|   9   |   103,0 ms |     914,4 ms |        50,8 ms |   101,4 ms |
|  10   |   101,5 ms |     911,8 ms |        50,6 ms |   103,0 ms |
|  11   |   103,2 ms |     914,2 ms |        51,7 ms |   101,3 ms |
|  12   |   101,4 ms |     913,8 ms |        50,9 ms |   102,4 ms |
|  13   |   102,5 ms |     912,7 ms |        50,8 ms |   100,9 ms |
|  14   |   101,0 ms |     909,6 ms |        50,6 ms |   101,1 ms |
|  15   |   101,2 ms |     909,3 ms |        50,8 ms |   100,9 ms |
|  16   |   100,9 ms |     911,3 ms |        50,8 ms |   102,3 ms |
|  17   |   102,5 ms |     913,7 ms |        50,4 ms |   100,9 ms |
|  18   |   100,9 ms |     910,7 ms |        51,5 ms |   101,5 ms |
|  19   |   101,5 ms |     911,8 ms |       101,2 ms |   101,4 ms |
|  20   |   101,5 ms |     915,2 ms |        51,6 ms |   100,8 ms |
|  21   |   100,9 ms |     910,4 ms |        50,5 ms |   101,9 ms |
|  22   |   102,0 ms |     915,1 ms |        50,8 ms |   101,8 ms |
|  23   |   101,9 ms |     911,3 ms |        51,6 ms |   101,7 ms |
|  24   |   101,9 ms |     914,8 ms |        51,4 ms |   101,0 ms |
|  25   |   101,1 ms |     912,4 ms |        50,9 ms |   100,7 ms |
|  26   |   100,8 ms |     910,8 ms |        50,8 ms |   101,4 ms |
|  27   |   101,5 ms |     916,5 ms |        50,8 ms |   101,1 ms |
|  28   |   101,1 ms |     910,1 ms |        50,7 ms |   102,6 ms |
|  29   |   102,7 ms |     913,5 ms |        51,3 ms |   101,2 ms |
|  30   |   101,2 ms |     912,3 ms |        50,8 ms |   101,5 ms |
|  31   |   101,5 ms |     914,6 ms |        51,6 ms |   101,1 ms |
|  32   |   101,1 ms |     909,6 ms |        50,8 ms |   100,9 ms |
|  33   |   100,9 ms |     911,7 ms |        50,9 ms |   101,3 ms |
|  34   |   101,4 ms |     913,5 ms |        51,7 ms |   101,3 ms |
|  35   |   101,4 ms |     912,7 ms |        50,4 ms |   101,0 ms |
|  36   |   101,0 ms |     911,5 ms |        50,8 ms |   101,6 ms |
|  37   |   101,7 ms |     911,4 ms |        51,8 ms |   101,5 ms |
|  38   |   101,6 ms |     910,7 ms |        50,8 ms |   101,3 ms |
|  39   |   101,4 ms |     912,2 ms |        50,7 ms |   101,7 ms |
|  40   |   101,8 ms |     911,5 ms |        50,3 ms |   102,0 ms |
|  41   |   102,1 ms |     915,6 ms |        50,8 ms |   101,5 ms |
|  42   |   101,5 ms |     914,5 ms |        51,2 ms |   101,5 ms |
|  43   |   101,6 ms |     912,8 ms |        50,7 ms |   101,0 ms |
|  44   |   101,1 ms |     912,5 ms |        50,9 ms |   101,2 ms |
|  45   |   101,3 ms |     914,5 ms |        51,4 ms |   100,9 ms |
|  46   |   101,0 ms |     911,5 ms |        50,5 ms |   100,8 ms |
|  47   |   100,8 ms |     911,7 ms |        50,8 ms |   102,3 ms |
|  48   |   102,5 ms |     914,8 ms |       101,9 ms |   101,5 ms |
|  49   |   101,6 ms |     913,2 ms |        51,3 ms |   101,0 ms |
|  50   |   101,0 ms |     907,6 ms |        50,6 ms |   101,0 ms |
|=======|============|==============|================|============|
|  avg  |    99,6 ms |     922,6 ms |        53,1 ms |   101,5 ms |
|_______|____________|______________|________________|____________|
 *** Average download speed for 43 161 600 bytes: 15 881,22 KB/s


SSH.NET download test, 50 iteration(s).
___________________________________________________________________
|  Run  |  Client Cr |  Connection  |    Download    |   Delete   |
|   1   |     0,8 ms |     156,5 ms |        35,2 ms |     4,2 ms |
|   2   |     4,3 ms |     162,4 ms |        33,5 ms |     4,1 ms |
|   3   |     4,1 ms |     165,7 ms |        33,0 ms |     3,7 ms |
|   4   |     3,7 ms |     162,9 ms |        34,2 ms |     3,6 ms |
|   5   |     3,6 ms |     170,9 ms |        33,0 ms |     4,3 ms |
|   6   |     4,4 ms |     171,1 ms |        36,4 ms |     4,0 ms |
|   7   |     4,1 ms |     181,1 ms |        33,8 ms |     3,6 ms |
|   8   |     3,6 ms |     161,5 ms |        33,9 ms |     3,7 ms |
|   9   |     3,7 ms |     176,6 ms |        36,8 ms |     4,0 ms |
|  10   |     4,0 ms |     193,9 ms |        32,9 ms |     3,9 ms |
|  11   |     3,9 ms |     179,4 ms |        33,9 ms |     3,6 ms |
|  12   |     3,6 ms |     190,0 ms |        33,6 ms |     4,1 ms |
|  13   |     4,1 ms |     170,9 ms |        33,7 ms |     3,5 ms |
|  14   |     3,5 ms |     178,8 ms |        33,7 ms |     3,9 ms |
|  15   |     3,9 ms |     170,0 ms |        32,7 ms |     4,0 ms |
|  16   |     4,1 ms |     176,7 ms |        34,5 ms |     4,7 ms |
|  17   |     4,8 ms |     169,6 ms |        33,2 ms |     4,0 ms |
|  18   |     4,0 ms |     189,9 ms |        35,0 ms |     3,6 ms |
|  19   |     3,6 ms |     173,6 ms |        33,4 ms |     3,5 ms |
|  20   |     3,6 ms |     168,4 ms |        33,0 ms |     3,7 ms |
|  21   |     3,8 ms |     166,5 ms |        34,3 ms |     3,7 ms |
|  22   |     3,7 ms |     168,0 ms |        35,6 ms |     3,6 ms |
|  23   |     3,6 ms |     169,1 ms |        33,5 ms |     3,7 ms |
|  24   |     3,8 ms |     163,9 ms |        33,1 ms |     3,5 ms |
|  25   |     3,5 ms |     167,4 ms |        34,8 ms |     4,9 ms |
|  26   |     4,9 ms |     159,9 ms |        36,3 ms |     3,9 ms |
|  27   |     3,9 ms |     177,8 ms |        32,9 ms |     3,5 ms |
|  28   |     3,5 ms |     165,8 ms |        38,3 ms |     3,9 ms |
|  29   |     3,9 ms |     160,1 ms |        32,1 ms |     3,7 ms |
|  30   |     3,7 ms |     168,0 ms |        33,0 ms |     3,9 ms |
|  31   |     4,0 ms |     174,2 ms |        35,2 ms |     4,0 ms |
|  32   |     4,0 ms |     170,8 ms |        36,1 ms |     3,5 ms |
|  33   |     3,6 ms |     177,5 ms |        35,4 ms |     3,9 ms |
|  34   |     3,9 ms |     178,4 ms |        36,4 ms |     3,6 ms |
|  35   |     3,6 ms |     163,0 ms |        33,3 ms |     3,9 ms |
|  36   |     4,0 ms |     194,6 ms |        35,3 ms |     3,5 ms |
|  37   |     3,5 ms |     165,6 ms |        34,4 ms |     4,1 ms |
|  38   |     4,2 ms |     172,6 ms |        32,9 ms |     3,7 ms |
|  39   |     3,8 ms |     160,1 ms |        33,9 ms |     3,6 ms |
|  40   |     3,7 ms |     162,1 ms |        41,3 ms |     4,1 ms |
|  41   |     4,1 ms |     173,9 ms |        32,2 ms |     3,9 ms |
|  42   |     3,9 ms |     162,5 ms |        33,7 ms |     4,0 ms |
|  43   |     4,0 ms |     163,7 ms |        33,5 ms |     3,5 ms |
|  44   |     3,5 ms |     202,2 ms |        33,6 ms |     3,5 ms |
|  45   |     3,6 ms |     170,2 ms |        33,5 ms |     3,8 ms |
|  46   |     3,9 ms |     168,7 ms |        33,3 ms |     4,7 ms |
|  47   |     4,7 ms |     164,4 ms |        33,7 ms |     3,8 ms |
|  48   |     3,9 ms |     166,5 ms |        36,2 ms |     3,6 ms |
|  49   |     3,6 ms |     165,6 ms |        32,8 ms |     3,6 ms |
|  50   |     3,6 ms |     157,6 ms |        32,0 ms |     4,4 ms |
|=======|============|==============|================|============|
|  avg  |     3,8 ms |     171,0 ms |        34,2 ms |     3,9 ms |
|_______|____________|______________|________________|____________|
 *** Average download speed for 43 161 600 bytes: 24 624,47 KB/s

[lochnar187]

Thank you, I'll have to try it with the dev build.

[camcombs]

Following because I'm having timeout issues, also with a SFTP server I can't control.

[lochnar187]

I pulled dev code today. Using the same test file and machines, I saw big improvements over the 2016.0.0 release. Looking good! I just wish I knew more about that server. It's got to have something to do with these transfer numbers.

Not to change the subject here but if anyone has suggestions on exploratory/diagnostic code to get more information about the server or transfer, please let me know.

WinSCP download test, 50 iteration(s).
___________________________________________________________________
|  Run  |  Client Cr |  Connection  |    Download    |   Delete   |
|   1   |     4.5 ms |   1,794.3 ms |       781.9 ms |   110.3 ms |
|   2   |   110.4 ms |   1,778.6 ms |       843.8 ms |   110.2 ms |
|   3   |   110.3 ms |   2,592.2 ms |       843.8 ms |   110.2 ms |
|   4   |   110.2 ms |   1,779.8 ms |       843.8 ms |   110.2 ms |
|   5   |   110.3 ms |   2,592.3 ms |       843.7 ms |   110.4 ms |
|   6   |   110.5 ms |   1,779.3 ms |       836.5 ms |   110.6 ms |
|   7   |   110.7 ms |   1,779.0 ms |       843.9 ms |   110.3 ms |
|   8   |   110.4 ms |   1,779.3 ms |       843.8 ms |   110.3 ms |
|   9   |   110.4 ms |   1,781.6 ms |       843.8 ms |   114.7 ms |
|  10   |   114.8 ms |   2,587.3 ms |     1,656.3 ms |   110.3 ms |
|  11   |   110.3 ms |   1,779.7 ms |       847.2 ms |   110.4 ms |
|  12   |   110.5 ms |   1,779.7 ms |       843.8 ms |   110.5 ms |
|  13   |   110.5 ms |   1,779.1 ms |       845.5 ms |   110.3 ms |
|  14   |   110.4 ms |   1,779.3 ms |       843.8 ms |   110.3 ms |
|  15   |   110.4 ms |   2,591.9 ms |       843.8 ms |   110.4 ms |
|  16   |   110.5 ms |   1,779.2 ms |       843.8 ms |   110.4 ms |
|  17   |   110.4 ms |   1,779.1 ms |       843.8 ms |   110.2 ms |
|  18   |   110.3 ms |   1,779.8 ms |       847.3 ms |   110.2 ms |
|  19   |   110.3 ms |   1,779.5 ms |       843.9 ms |   110.4 ms |
|  20   |   110.5 ms |   1,780.5 ms |       843.7 ms |   110.4 ms |
|  21   |   110.5 ms |   1,779.2 ms |       843.9 ms |   110.3 ms |
|  22   |   110.4 ms |   1,779.3 ms |       843.8 ms |   110.3 ms |
|  23   |   110.4 ms |   1,771.2 ms |       844.4 ms |   110.4 ms |
|  24   |   110.5 ms |   2,591.7 ms |       843.9 ms |   110.3 ms |
|  25   |   110.4 ms |   2,591.7 ms |       843.8 ms |   110.2 ms |
|  26   |   110.3 ms |   1,779.7 ms |       843.8 ms |   110.3 ms |
|  27   |   110.3 ms |   1,779.7 ms |       843.8 ms |   110.3 ms |
|  28   |   110.3 ms |   1,779.7 ms |       843.8 ms |   110.2 ms |
|  29   |   110.3 ms |   1,779.7 ms |       843.8 ms |   110.2 ms |
|  30   |   110.3 ms |   2,592.3 ms |       843.8 ms |   110.4 ms |
|  31   |   110.5 ms |   2,591.8 ms |       843.9 ms |   110.1 ms |
|  32   |   110.2 ms |   1,779.5 ms |       843.9 ms |   110.4 ms |
|  33   |   110.5 ms |   2,591.8 ms |     1,656.3 ms |   110.3 ms |
|  34   |   110.4 ms |   1,779.3 ms |     1,656.3 ms |   110.3 ms |
|  35   |   110.4 ms |   1,779.3 ms |       843.8 ms |   110.3 ms |
|  36   |   110.3 ms |   1,779.6 ms |       843.8 ms |   110.5 ms |
|  37   |   110.6 ms |   1,780.8 ms |       843.8 ms |   110.4 ms |
|  38   |   110.4 ms |   1,779.3 ms |       843.7 ms |   110.5 ms |
|  39   |   110.6 ms |   1,779.3 ms |       843.8 ms |   110.5 ms |
|  40   |   110.5 ms |   1,779.2 ms |       847.9 ms |   110.6 ms |
|  41   |   110.7 ms |   2,592.7 ms |       843.8 ms |   110.4 ms |
|  42   |   110.5 ms |   2,591.6 ms |       843.8 ms |   111.2 ms |
|  43   |   111.3 ms |   1,778.2 ms |       843.8 ms |   110.1 ms |
|  44   |   110.2 ms |   1,780.0 ms |       843.7 ms |   110.4 ms |
|  45   |   110.4 ms |   1,779.3 ms |     1,656.3 ms |   110.3 ms |
|  46   |   110.4 ms |   1,780.4 ms |       843.8 ms |   110.5 ms |
|  47   |   110.6 ms |   1,779.2 ms |       843.9 ms |   110.4 ms |
|  48   |   110.5 ms |   2,591.6 ms |       843.8 ms |   110.2 ms |
|  49   |   110.3 ms |   1,779.2 ms |       843.8 ms |   110.2 ms |
|  50   |   110.3 ms |   1,779.8 ms |       843.8 ms |   110.1 ms |
|=======|============|==============|================|============|
|  avg  |   108.4 ms |   1,974.6 ms |       907.7 ms |   110.4 ms |
|_______|____________|______________|________________|____________|
 *** Average download speed for 42,700,800 bytes: 918.82 KB/s


SSH.NET download test, 50 iteration(s).
___________________________________________________________________
|  Run  |  Client Cr |  Connection  |    Download    |   Delete   |
|   1   |    10.6 ms |     854.5 ms |     1,237.7 ms |    36.2 ms |
|   2   |    36.2 ms |     790.2 ms |     1,234.4 ms |    30.9 ms |
|   3   |    30.9 ms |   1,274.8 ms |     1,370.2 ms |    30.4 ms |
|   4   |    30.4 ms |   1,172.6 ms |     1,360.5 ms |    31.0 ms |
|   5   |    31.1 ms |   1,214.2 ms |     1,373.9 ms |    30.6 ms |
|   6   |    30.6 ms |   1,183.1 ms |     1,338.5 ms |    31.3 ms |
|   7   |    31.3 ms |   1,135.0 ms |     1,357.8 ms |    29.9 ms |
|   8   |    29.9 ms |   1,249.5 ms |     1,413.4 ms |    30.7 ms |
|   9   |    30.7 ms |   1,166.6 ms |     1,351.1 ms |    31.7 ms |
|  10   |    31.7 ms |   1,206.5 ms |     1,276.2 ms |    29.8 ms |
|  11   |    29.8 ms |   1,190.5 ms |     1,348.7 ms |    31.6 ms |
|  12   |    31.6 ms |   1,403.9 ms |     1,385.1 ms |    29.9 ms |
|  13   |    29.9 ms |   1,133.3 ms |     1,367.0 ms |    30.5 ms |
|  14   |    30.5 ms |   1,260.8 ms |     1,349.0 ms |    30.1 ms |
|  15   |    30.2 ms |   1,171.7 ms |     1,394.7 ms |    30.9 ms |
|  16   |    30.9 ms |   1,164.9 ms |     1,360.2 ms |    32.2 ms |
|  17   |    32.3 ms |   1,267.7 ms |     1,346.9 ms |    30.1 ms |
|  18   |    30.1 ms |   1,216.1 ms |     1,380.3 ms |    30.3 ms |
|  19   |    30.4 ms |     778.4 ms |     1,247.8 ms |    30.7 ms |
|  20   |    30.7 ms |   1,321.7 ms |     1,370.9 ms |    29.8 ms |
|  21   |    29.8 ms |     791.9 ms |     1,225.3 ms |    30.4 ms |
|  22   |    30.4 ms |   1,096.9 ms |     1,223.9 ms |    30.3 ms |
|  23   |    30.3 ms |   1,450.5 ms |     1,286.6 ms |    30.6 ms |
|  24   |    30.7 ms |   1,296.2 ms |     1,351.7 ms |    30.6 ms |
|  25   |    30.7 ms |   1,051.9 ms |     1,301.3 ms |    31.8 ms |
|  26   |    31.9 ms |   1,252.0 ms |     1,342.4 ms |    30.7 ms |
|  27   |    30.7 ms |     798.5 ms |     1,241.6 ms |    30.5 ms |
|  28   |    30.5 ms |   1,257.4 ms |     1,413.2 ms |    29.8 ms |
|  29   |    29.8 ms |   1,198.3 ms |     1,317.6 ms |    41.7 ms |
|  30   |    41.7 ms |   1,175.5 ms |     1,470.8 ms |    30.6 ms |
|  31   |    30.6 ms |   1,207.0 ms |     1,355.9 ms |    31.6 ms |
|  32   |    31.7 ms |   1,184.3 ms |     1,366.4 ms |    29.9 ms |
|  33   |    29.9 ms |   1,413.0 ms |     1,689.5 ms |    30.4 ms |
|  34   |    30.5 ms |     963.7 ms |     1,604.3 ms |    31.3 ms |
|  35   |    31.4 ms |   6,153.2 ms |     2,574.9 ms |    30.1 ms |
|  36   |    30.1 ms |     997.3 ms |     1,421.5 ms |    29.9 ms |
|  37   |    30.0 ms |   3,241.6 ms |     1,688.5 ms |    30.4 ms |
|  38   |    30.5 ms |   1,308.0 ms |     1,646.8 ms |    42.8 ms |
|  39   |    42.8 ms |   1,216.4 ms |     1,637.1 ms |    29.9 ms |
|  40   |    29.9 ms |   1,562.0 ms |     1,438.5 ms |    31.5 ms |
|  41   |    31.5 ms |   1,407.7 ms |     1,806.8 ms |    30.6 ms |
|  42   |    30.7 ms |   1,360.6 ms |     1,512.1 ms |    30.1 ms |
|  43   |    30.1 ms |   1,659.3 ms |     1,527.7 ms |    30.7 ms |
|  44   |    30.7 ms |   1,623.3 ms |     1,753.2 ms |    30.3 ms |
|  45   |    30.3 ms |   1,312.4 ms |     1,426.0 ms |    31.3 ms |
|  46   |    31.3 ms |     790.7 ms |     1,278.9 ms |    29.7 ms |
|  47   |    29.8 ms |     791.9 ms |     1,380.5 ms |    30.4 ms |
|  48   |    30.4 ms |   1,412.9 ms |     1,393.2 ms |    31.1 ms |
|  49   |    31.1 ms |     821.7 ms |     1,307.3 ms |    30.7 ms |
|  50   |    30.7 ms |   1,171.7 ms |     1,419.0 ms |    29.3 ms |
|=======|============|==============|================|============|
|  avg  |    30.8 ms |   1,322.5 ms |     1,425.3 ms |    31.2 ms |
|_______|____________|______________|________________|____________|
 *** Average download speed for 42,700,800 bytes: 585.12 KB/s

[ceastwood]

I haven't done any thorough testing as above, but I was just evaluating the library and the performance issue is large in the current NuGet package (v2016.0.0). Once I get a chance in near the future I will revisit to test further but thought it might help if I added a comment.

The server is internal to the corporate network and always / easily provides near gigabit downloads when using a standalone sftp client (FileZilla). Connectivity is > 1Gbps

Using SSH.NET SftpClient to a memory stream will not go any faster than ~2.78MB/s. Also tried to provide a buffer the full size of the desired file to the memorystream constructor without luck.

Just downloaded the WinSCP NuGet package and it achieves ~70MB/s but there are various issues with that project as well.

Thanks,

[drieseng]

@lochnar187 I'll do some tests with WS-FTP later this week, or early next week. I may need more information on your setup at the point.

[drieseng]

@ceastwood Those numbers really trouble me. Can you provide more info on that SSH server (software, version, crypto used, ...). If not, I could provide a custom built version of SSH.NET that adds more debug output).

[lochnar187]

@drieseng I'll give you all the info I have, sadly that's not much for the WS-FTP server as it's not mine. Just let me know what you need.

For the moment, here's a verbose log from FileZilla's connection to that server:

Status: Connecting to xxxxxxxxxxxxxxx...
Trace:  Going to execute "C:\Program Files\FileZilla FTP Client\fzsftp.exe"
Response:   fzSftp started
Trace:  CSftpControlSocket::ConnectParseResponse(fzSftp started)
Trace:  CSftpControlSocket::SendNextCommand()
Trace:  CSftpControlSocket::ConnectSend()
Command:    open "xxxxxxxxxxx@xxxxxxxxxxxxxxx" 22
Trace:  Looking up host "xxxxxxxxxxxxxxx"
Trace:  Connecting to xx.xx.xx.xx port 22
Trace:  Server version: SSH-2.0-WS_FTP-SSH_7.6.3
Trace:  Using SSH protocol version 2
Trace:  We claim version: SSH-2.0-PuTTY_Local:_Jun__1_2014_11:08:49
Trace:  Using Diffie-Hellman with standard group "group14"
Trace:  Doing Diffie-Hellman key exchange with hash SHA-1
Trace:  Host key fingerprint is:
Trace:  ssh-rsa 1024 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
Trace:  Initialised AES-256 CBC client->server encryption
Trace:  Initialised HMAC-SHA1 client->server MAC algorithm
Trace:  Initialised AES-256 CBC server->client encryption
Trace:  Initialised HMAC-SHA1 server->client MAC algorithm
Command:    Pass: ********
Trace:  Sent password
Trace:  Access granted
Trace:  Opened channel for session
Trace:  Started a shell/command
Status: Connected to xxxxxxxxxxxxxxx
Trace:  CSftpControlSocket::ConnectParseResponse()
Trace:  CSftpControlSocket::ResetOperation(0)
Trace:  CControlSocket::ResetOperation(0)
Trace:  CFileZillaEnginePrivate::ResetOperation(0)
Status: Retrieving directory listing...
Trace:  CSftpControlSocket::SendNextCommand()
Trace:  CSftpControlSocket::ChangeDirSend()
Command:    pwd
Response:   Current directory is: "/xxxxxxxxxxx"
Trace:  CSftpControlSocket::ResetOperation(0)
Trace:  CControlSocket::ResetOperation(0)
Trace:  CSftpControlSocket::ParseSubcommandResult(0)
Trace:  CSftpControlSocket::ListSubcommandResult()
Trace:    state = 1
Trace:  CSftpControlSocket::SendNextCommand()
Trace:  CSftpControlSocket::ListSend()
Trace:    state = 2
Command:    ls
Status: Listing directory /xxxxxxxxxxx
Trace:  CSftpControlSocket::ListParseResponse()
Trace:  CSftpControlSocket::ResetOperation(0)
Trace:  CControlSocket::ResetOperation(0)
Status: Directory listing successful
Trace:  CFileZillaEnginePrivate::ResetOperation(0)

[spkane86]

The reason for the poor performance is that requests aren't pipelining despite the code appearing built to do so.

Say the buffers are configured such that you can receive 5 SSH_FXP_READ responses (SSH_FXP_DATA) before you can read any more. The pattern I'm seeing is like this for downloads, in shorthand:

READ 0->
<- DATA 0
READ 1 ->
<- DATA 1
READ 2 ->
<- DATA 2
READ 3 ->
<- DATA 3
READ 4 ->
<- DATA 4
...

What you want to see is something more like this:

READ 0 ->
READ 1 ->
READ 2 ->
READ 3->
READ 4->
<- DATA 0
READ 5 ->
<- DATA 1
READ 6 ->
<- DATA 2
READ 7 ->
<- DATA 3
READ 8->
<- DATA 4
READ 9->
...

Does that make sense? Since SFTP has a 32KB max data size, with the pattern I'm seeing now, there is a round-trip-time inflicted for each 32KB in the file, which is why buffer sizes don't really matter much. It's only actually buffering 32KB before writing it right away.

From my cursory reading of the code, it may be due to the locking on _requests dictionary in SftpSession or perhaps the SftpFileStream itself. Another thought I had is that since response handling is event-driven, you're also likely to be stuck handling a response when you could be sending one out, especially when there is low latency on the connection. Disk I/O is more costly than sending a new request, and since you're handling responses right away and locking the _requests in the meantime, it can't get another request out by the time it's received a new response to handle from the previous request.

It seems to be an issue on writes as well. You want to send out as many writes as you can until you block waiting for WINDOW_ADJUST. That could be a similar thing, where WRITE's get built/sent while a lock is held, preventing further WRITE's from being built/sent simultaneously because you're already handling a STATUS.

Not really sure I'm anywhere close on the underlying cause in the code. But hey, it's pretty to look at, so maybe I'll look some more soon.

If it does have something to do with locking or event handling, I'm not sure the best solution for your code. When I've implemented pipelining on an SFTP client in the past, I had to kind of refactor the response handling so that it was closely in-tune with request sending, such that I had more direct control over when to send new request (i.e. immediately after receiving a response). In any case the most important thing is to completely fill the pipe at the start of the transfer, and then the existing paradigm should work relatively well.

That said, you really don't want to assume it won't start falling behind, by handling more responses than making new requests, but handling that is a lot more difficult than simply putting some blocker up on your response handling while you're busy filling the pipe at the start. I'd probably start there to see if it even does try to pipeline the requests in the first place. You might be surprised at the results.

[spkane86]

Just occurred to me that SftpSession.RequestRead is essentially synchronous. That would do it.

[drieseng]

We may effectively be able to send multiple read requests at once; either by first checking what the size of the remote file is, and determine the optimal number of the requests to send in parallel, or by sending a given number of requests and ignoring those responses that return an EOF (and stop sending any further requests when any of these async requests return an EOF).

We would however need to write the responses to those requests in sequence, as such we would need to buffer more data and - as a consequence- consume more memory.

I currently don't have time to do a POC for this, but please don't hesitate to take a stab at this.