Faster SFTP to FTP download

0 votes
asked Aug 20 by RK (180 points)
edited Aug 20 by RK

Hi, continuation to my above query, I am currently downloading the PDF files from an SFTP location to an FTP location, files to download may range from 100-5000.
But the logic below doesn't seem to work faster, it takes almost 2hrs for 3000 files to download.

Please find the code below. If you can you please suggest if there is a way out.

foreach (var file in lstFileDetails)
{
if (!string.IsNullOrEmpty(file.dirPath))
{
string pdfFileName = file.pdfFileName;
source = AWSPdfFilePath;
destination = file.dirPath + @"\" + pdfFileName;

    if (sftp.FileExists(source + @"/" + pdfFileName))
    {
        isFileExists = true;
        fileName = pdfFileName;
    }       
    else
    {
        fileName = listpdfNames.AsParallel().Where(name => name.ToLower().Contains(pdfFileName.ToLower())).FirstOrDefault();
        if (!string.IsNullOrEmpty(fileName))
        {
            isFileExists = true;
        }
    }

    if (isFileExists)
    {
        sftp.GetFile(source + "/" + fileName, destination));

        //IAsyncResult asyncResult = sftp.BeginGetFile(source + "/" + fileName, destination, null, null);
        //sftp.EndGetFile(asyncResult);
    }

    if (!isFileExists)
    {
        string message = "PDF file " + pdfFileName + "</br></br>";
        messageForTeams.Append(message);
    }
}

};

related to an answer for: SFTP GetFile supports case sensitive
Applies to: Rebex SFTP

1 Answer

0 votes
answered Aug 20 by Pavel Matyska (13,460 points)

Hi,

Please use this code to determine your actual download speed:

using (Sftp sftp = new Sftp())
{
    // connect and login as you are used to
    sftp.Connect(server);
    sftp.Login(user, password);

    int[] fileSizes = { 1024 * 1024 /*1MB*/, 10 * 1024 * 1024 /*10MB*/, 20 * 1024 * 1024 /*20MB*/, 100 * 1024 * 1024 /*100MB*/};
    Random rng = new Random();

    foreach (var size in fileSizes)
    {
        Console.WriteLine("Preparing {0} MB of data to process.", size / (1024 * 1024));
        byte[] rngFile = new byte[size];
        rng.NextBytes(rngFile);

        var upload = new MemoryStream(rngFile);
        string remotePath = size.ToString() + ".rng";

        Console.WriteLine("Uploading {0} bytes of data.", size);
        sftp.PutFile(upload, remotePath);

        DateTime start = DateTime.Now;

        Console.WriteLine("{0} {1} download starts.", start.ToString("HH:mm:ss.ffff"), remotePath);
        sftp.GetFile(remotePath, Stream.Null);

        DateTime end = DateTime.Now;
        Console.WriteLine("{0} {1} download ends.", end.ToString("HH:mm:ss.ffff"), remotePath);

        TimeSpan duration = end - start;
        Console.WriteLine("Download took {0} of time.", duration.ToString("g"));
        Console.WriteLine("Download speed: {0} MB/s", size / (1024 * 1024) / (duration.TotalMilliseconds / 1000d));
        Console.WriteLine("Clean up.");
        sftp.DeleteFile(remotePath);
        Console.WriteLine("-------------");                    
    }
}

You can then count how much time should your batch of files take to download.

Please let us know what your output is from this sample code.

commented Aug 20 by RK (180 points)
Hi, based on the code sample shared I have used the GetFile as the PutFile process is already done by another process.

My PDF's are basically in KB's from 100KB's-500KB's, but the PDF file count is more.

Here is the log:
14:29:24.2265 /lob/Client/QA/44251192_43665097_Investment Statement_2_1435999.pdf download starts.
14:29:30.6573 /lob/Client/QA/44251192_43665097_Investment Statement_2_1435999.pdf download ends.
Download took 0:00:06,4307564 of time.
Download speed: 0,155502702605871 MB/s
-------------
14:29:37.4348 /lob/Client/QA/44251192_43665097_Investment Statement_2_1435999.pdf download starts.
14:29:41.4318 /lob/Client/QA/44251192_43665097_Investment Statement_2_1435999.pdf download ends.
Download took 0:00:03,9969651 of time.
Download speed: 2,50189825275182 MB/s
-------------
14:29:44.8716 /lob/Client/QA/44251192_43665097_Investment Statement_2_1435999.pdf download starts.
14:29:48.1316 /lob/Client/QA/44251192_43665097_Investment Statement_2_1435999.pdf download ends.
Download took 0:00:03,2599185 of time.
Download speed: 6,13512270322095 MB/s
-------------
14:29:51.3055 /lob/Client/QA/44251192_43665097_Investment Statement_2_1435999.pdf download starts.
14:29:54.9166 /lob/Client/QA/44251192_43665097_Investment Statement_2_1435999.pdf download ends.
Download took 0:00:03,6110206 of time.
Download speed: 27,6930018067468 MB/s
-------------

I am looking for the performance to get better related to GetFile as it takes almost 2 hours for 3000 files. So i am expecting for it to complete atleast half of the time it currently takes.

Kindly advice.
commented Aug 20 by Lukas Pokorny (113,730 points)
Thanks! This looks like the actual transfer of file data is reasonably fast, but there is a big overhead while opening/closing each file. Please create a communication log (see https://www.rebex.net/kb/logging/ for details) showing several of these transfers and either post a part of it here or mail it to us for analysis. Based on the log, we would be able to tell where exactly those delays occur, and hopefully come up with a way to make the process faster.
commented Aug 21 by RK (180 points)
Hi Lukas,

Please find the log below for few files as per your suggestion above. (Posting the logs in 2 comments before of size limit)

2020-08-21 10:37:15.451 Opening log file.
2020-08-21 10:37:15.453 INFO FileLogWriter(1)[4] Info: Assembly: Rebex.Common 2018 R4 for .NET 2.0-3.5
2020-08-21 10:37:15.455 INFO FileLogWriter(1)[4] Info: Platform: Windows 6.2.9200 64-bit; CLR: 4.0.30319.42000
2020-08-21 10:37:15.456 DEBUG FileLogWriter(1)[4] Info: Culture: en; Windows-1252
2020-08-21 10:37:15.461 INFO Sftp(2)[4] Command: SSH_FXP_STAT (13, '/lob/Vun/QA/44251192_43665097_Investment Statement_2 DONGA_1435999.pdf')
2020-08-21 10:37:15.693 INFO Sftp(2)[4] Response: SSH_FXP_ATTRS (13)
2020-08-21 10:37:16.145 INFO Sftp(2)[4] Command: SSH_FXP_OPEN (14, '/lob/Vun/QA/44251192_43665097_Investment Statement_2 DONGA_1435999.pdf', 1)
2020-08-21 10:37:16.410 INFO Sftp(2)[4] Response: SSH_FXP_HANDLE (14, 0x31)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (15, 0x31, 0, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (16, 0x31, 28672, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (17, 0x31, 57344, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (18, 0x31, 86016, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (19, 0x31, 114688, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (20, 0x31, 143360, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (21, 0x31, 172032, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (22, 0x31, 200704, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (23, 0x31, 229376, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (24, 0x31, 258048, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (25, 0x31, 286720, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (26, 0x31, 315392, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (27, 0x31, 344064, 28672)
2020-08-21 10:37:16.413 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (28, 0x31, 372736, 28672)
2020-08-21 10:37:16.414 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (29, 0x31, 401408, 28672)
2020-08-21 10:37:16.414 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (30, 0x31, 430080, 28672)
2020-08-21 10:37:17.006 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (15, 28672 bytes)
2020-08-21 10:37:17.006 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (31, 0x31, 458752, 28672)
2020-08-21 10:37:17.085 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (16, 28672 bytes)
2020-08-21 10:37:17.085 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (32, 0x31, 487424, 28672)
2020-08-21 10:37:17.085 DEBUG Sftp(2)[4] SSH: Adjusted local window size: 0 -> 131072.
2020-08-21 10:37:17.245 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (17, 28672 bytes)
2020-08-21 10:37:17.245 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (33, 0x31, 516096, 28672)
2020-08-21 10:37:17.403 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (18, 28672 bytes)
2020-08-21 10:37:17.404 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (34, 0x31, 544768, 28672)
2020-08-21 10:37:17.566 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (19, 28672 bytes)
2020-08-21 10:37:17.566 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (35, 0x31, 573440, 28672)
2020-08-21 10:37:17.715 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (20, 28672 bytes)
2020-08-21 10:37:17.715 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (36, 0x31, 602112, 28672)
2020-08-21 10:37:17.883 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (21, 25057 bytes)
2020-08-21 10:37:17.883 DEBUG Sftp(2)[4] Info: Waiting for 15 outstanding read requests to arrive.
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (22, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (23, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (24, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (25, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (26, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (27, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (28, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (29, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (30, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (31, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (32, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (33, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (34, 1, '')
2020-08-21 10:37:17.883 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (35, 1, '')
2020-08-21 10:37:17.953 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (36, 1, '')
2020-08-21 10:37:17.953 DEBUG Sftp(2)[4] Info: Requests arrived.
2020-08-21 10:37:17.953 INFO Sftp(2)[4] Command: SSH_FXP_CLOSE (37, 0x31)
2020-08-21 10:37:18.151 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (37, 0, 'Success')
commented Aug 21 by RK (180 points)
2020-08-21 10:37:18.304 INFO Sftp(2)[4] Command: SSH_FXP_STAT (38, '/lob/Vun/QA/44252925_43666830_Investment Statement_HOLDINGS_1317596.pdf')
2020-08-21 10:37:18.537 INFO Sftp(2)[4] Response: SSH_FXP_ATTRS (38)
2020-08-21 10:37:18.545 INFO Sftp(2)[4] Command: SSH_FXP_OPEN (39, '/lob/Vun/QA/44252925_43666830_Investment Statement_HOLDINGS_1317596.pdf', 1)
2020-08-21 10:37:18.780 INFO Sftp(2)[4] Response: SSH_FXP_HANDLE (39, 0x32)
2020-08-21 10:37:18.780 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (40, 0x32, 0, 28672)
2020-08-21 10:37:18.780 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (41, 0x32, 28672, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (42, 0x32, 57344, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (43, 0x32, 86016, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (44, 0x32, 114688, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (45, 0x32, 143360, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (46, 0x32, 172032, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (47, 0x32, 200704, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (48, 0x32, 229376, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (49, 0x32, 258048, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (50, 0x32, 286720, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (51, 0x32, 315392, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (52, 0x32, 344064, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (53, 0x32, 372736, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (54, 0x32, 401408, 28672)
2020-08-21 10:37:18.781 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (55, 0x32, 430080, 28672)
2020-08-21 10:37:19.066 DEBUG Sftp(2)[4] SSH: Adjusted local window size: 29513 -> 114688.
2020-08-21 10:37:19.101 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (40, 28672 bytes)
2020-08-21 10:37:19.101 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (56, 0x32, 458752, 28672)
2020-08-21 10:37:19.377 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (41, 28672 bytes)
2020-08-21 10:37:19.377 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (57, 0x32, 487424, 28672)
2020-08-21 10:37:19.377 DEBUG Sftp(2)[4] SSH: Adjusted local window size: 0 -> 131072.
2020-08-21 10:37:19.528 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (42, 28672 bytes)
2020-08-21 10:37:19.528 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (58, 0x32, 516096, 28672)
2020-08-21 10:37:19.612 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (43, 28672 bytes)
2020-08-21 10:37:19.612 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (59, 0x32, 544768, 28672)
2020-08-21 10:37:19.860 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (44, 28672 bytes)
2020-08-21 10:37:19.860 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (60, 0x32, 573440, 28672)
2020-08-21 10:37:19.947 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (45, 28672 bytes)
2020-08-21 10:37:19.948 DEBUG Sftp(2)[4] Command: SSH_FXP_READ (61, 0x32, 602112, 28672)
2020-08-21 10:37:20.121 DEBUG Sftp(2)[4] Response: SSH_FXP_DATA (46, 24835 bytes)
2020-08-21 10:37:20.121 DEBUG Sftp(2)[4] Info: Waiting for 15 outstanding read requests to arrive.
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (47, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (48, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (49, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (50, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (51, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (52, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (53, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (54, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (55, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (56, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (57, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (58, 1, '')
2020-08-21 10:37:20.121 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (59, 1, '')
2020-08-21 10:37:20.122 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (60, 1, '')
2020-08-21 10:37:20.140 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (61, 1, '')
2020-08-21 10:37:20.140 DEBUG Sftp(2)[4] Info: Requests arrived.
2020-08-21 10:37:20.140 INFO Sftp(2)[4] Command: SSH_FXP_CLOSE (62, 0x32)
2020-08-21 10:37:20.344 INFO Sftp(2)[4] Response: SSH_FXP_STATUS (62, 0, 'Success')
commented Aug 24 by Lukas Pokorny (113,730 points)
It's hard to draw any firm conclusion from just two file transfers, but apparently it took almost 300ms for the server to respond to SSH_FXP_OPEN request, at least 300ms to respond to the first of a sequence of SSH_FXP_READ requests, and around 200ms to respond to SSH_FXP_CLOSE request. That's at least a 800ms delay per file. If these file transfers are typical examples, these delays alone would account for 40 minutes out of those 2 hours. But unfortunately, this doesn't seem to be client-side delays, so the SFTP client cannot do anything about it. How long does it take to transfer the same list of files using a third-party SFTP client such as PuTTY psftp.exe?

One sure way to speed up the transfer would be to pack all those .pdf files into a ZIP file, upload the ZIP file, and unzip it at the server. Unfortunately, the last part cannot be done using the SFTP protocol alone and would require access to simple shell commands at the server.
...