Addressing Degradation of Automated Download Speed (PowerShell): Removal of Optimization = No Change

Advertisement

corey.mcentyre
Donor
Joined:
Posts:
6
Location:
Norway, Maine

Addressing Degradation of Automated Download Speed (PowerShell): Removal of Optimization = No Change

Our automated download of about 70 files (4-5 Gb of data nightly) has recently slowed significantly. We were seeing roughly 6–7 minutes total download time which has slowly moved into the 40–45 minute area. I spoke with a network tech at our vendor who said they handle 100's of customers downloads and they are averaging 55Mb/sec. We were at 8–10, but are now are seeing 1–2.

We were running the WinSCP Module in PowerShell and when it slowed to 45 minutes, I tried re-coding using the WinSCP.exe so I could take advantage of the -rawsettings and implement some of the suggested solutions (most notably trying Blowfish and Sendbuf=0). Our run of this code was also in the 40 minute range. The network team here worked with me to do a test from the same machine internally to one of their externally hosted (over the internet like our vendor) sites and we achieved ~20MB/sec in our test.

I'm hoping there is a setting I'm missing that will work with the specific host we are hitting as our test run demonstrated that we are not bandwidth limited.... and the vendor demonstrated they are handling multiple clients at the same time of day and pushing at high speed.

Code has been simplified to the pull portion only as none of the other logic is time consuming and the logs show the time is all related to download speed.

If there is a setting that will get us flying again, you'll have my gratitude (and some nerd points).

I've attached Session and Debug logs as well as the output log from our full script and a graph showing the behavior (it has been a slow progression of performance degradation).

Thanks in advance for any advice!!

WinSCP Version 5.9.1.0
Windows Server 2016 (v1607 OS Build 14393.7428)

Import-Module WinSCP
$PDPRunType        = "DAILY" # Added just for testing purposes
$TodayDateString   = Get-Date -Format "yyyyMMddhhmmss"
$TodayDateShortStr = Get-Date -Format "yyyyMMdd"
$PDPRootDir        = "C:\Projects\PullDailyPDP"                    
$WinSCPBinPath     = "$PDPRootDir\Bin\WinSCP.exe"
$SessionLog        = "$LogDir\WinSCP_Session_$TodayDateString.txt"
$DebugLog          = "$LogDir\WinSCP_Debug_$TodayDateString.txt"
$PMONDIRNAME       = "PMONDIR"
$F25UN             = "UserName"
$F25FingerPrint    = "ssh-rsa 2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx"
$F25Site           = "sftpSite.com"
$F25PWSecure       = Get-Content "C:\Projects\Credentials\VendorPull25.txt" | ConvertTo-SecureString
$F25BSTR           = [System.Runtime.InteropServices.Marshal]::SecureStringToBSTR($F25PWSecure)
$F25PW             = [System.Runtime.InteropServices.Marshal]::PtrToStringAuto($F25BSTR)                    
$TimeOutMin        = 10
$TimeOutMinTS      = New-Timespan -Minutes $TimeOutMin
 
## Set Up for Test
$F25PullDir       = "/USER/UserPath/PRIME/DAILY3I010"
$BackupDirRoot    = "E:\Backup\Daily"
$DailyPDPDir      = "E:\Prime\Daily"
$LocalPMonFile    = "$TodaysBkpDir\$PMONDIRNAME"
 
 
$TodaysBkpDir     = "$BackupDirRoot\$TodayDateShortStr"
#
# Set up WinSCP Options
#
$F25session         = New-Object WinSCP.Session
$F25sessionOptions  = New-Object WinSCP.SessionOptions
$F25transferOptions = New-Object WinSCP.TransferOptions
#
# WinSCP Session and Transfer Options
#
$F25session.ExecutablePath               = $WinSCPBinPath
$F25Session.DebugLogPath                 = $DebugLog
$F25Session.SessionLogPath               = $SessionLog
$F25transferOptions.TransferMode         = [WinSCP.TransferMode]::Binary
$F25sessionOptions.Protocol              = [WinSCP.Protocol]::Sftp
$F25sessionOptions.HostName              = $F25Site
$F25sessionOptions.UserName              = $F25UN
$F25sessionOptions.Password              = $F25PW
$F25sessionOptions.SshHostKeyFingerprint = $F25FingerPrint
$F25sessionOptions.Timeout               = $TimeOutMinTS
#
# Raw settings to speed download MB/s
#
$F25sessionOptions.AddRawSettings("Cipher", "blowfish,aes,chacha20,aesgcm,3des,WARN,des,arcfour")
$F25sessionOptions.AddRawSettings("PreserveDirectoryChanges", "0")
$F25sessionOptions.AddRawSettings("SendBuf", "0")
$F25sessionOptions.AddRawSettings("SshSimple", "0")
$F25session.Open($F25sessionOptions)
$Files2Pull = Get-Content -Path $LocalPMonFile
If ($F25Session.Opened)
{
   Foreach ($FileName in $Files2Pull)
   {
      $FileName   = $FileName.Trim()
      $RemoteFile = "$F25PullDir/$FileName"
      $PullResult = Receive-WinSCPItem -WinSCPSession $F25Session -Path $RemoteFile -Destination $TodaysBkpDir -Remove
   }
}

Description: Graph of download times showing degradation

PDP_Speed_Issues.jpg

Description: Our code's log file from last night's run showing download time per file.
Description: Debug and Session Logs

Reply with quote

Advertisement

martin
Site Admin
martin avatar
Joined:
Posts:
41,454
Location:
Prague, Czechia

Re: Addressing Degradation of Automated Download Speed (PowerShell): Removal of Optimization = No Change

Do you have logs from the time, when the transfer speed was decent?

Reply with quote

corey.mcentyre
Donor
Joined:
Posts:
6
Location:
Norway, Maine

Re: Addressing Degradation of Automated Download Speed (PowerShell): Removal of Optimization = No Change

Unfortunately I coded it to keep 7 days of logs and it wasn't until the performance had gotten to the 30–40 minute level that I started to dig in. :-/
I take it from your reply that there is nothing wrong with our settings which is cool. I'm glad I made the right choices on them, but bummed they were not the root cause.
If you (or anyone else reading) has ideas on what could cause this behavior, I'm willing to try experimenting with alternate settings/methods.
Thanks!

Reply with quote

martin
Site Admin
martin avatar
Joined:
Posts:
41,454
Location:
Prague, Czechia

Re: Addressing Degradation of Automated Download Speed (PowerShell): Removal of Optimization = No Change

Indeed, I do not see anything suspicious in the logs nor the code.
Did you try another client? Or WinSCP on another machine?

Thanks for your donation!

Reply with quote

corey.mcentyre
Donor
Joined:
Posts:
6
Location:
Norway, Maine

Re: Addressing Degradation of Automated Download Speed (PowerShell): Removal of Optimization = No Ch

Other than testing my code against the other sftp server set up by one of my co-workers (which pulled 5Gb in ~5min as expected), I haven't tried anything new against the vendor beyond changing settings. They have provided us with their preferred client (MOVEit-EZ). We're not big fans of using MOVEit products, but I may set it up for a speed comparison.

As for the donation ...

I've been using these posts/replies as an anonymous guest to solve problems and improve my code. You and the community here has (unknowingly) helped me many times over as a result of the questions/answers and examples - my donation was long overdue and is very deserved. :)

I'm a big fan of the client and the PowerShell documentation and examples. Its all fantastic work. I should have paid my dues ages ago.

Thank you for all of that .. and for your exceptional support.

Reply with quote

Advertisement

corey.mcentyre
Donor
Joined:
Posts:
6
Location:
Norway, Maine

Possible Solution .. Download Time is Now at 11 Minutes

I just wanted to update that I added a few more raw settings and saw a large improvement in speed. Since the slowness had been a progression as opposed to an overnight change, I went back and looked through options related to caching. I saw that we had Directory Caching set and it was marked as permanent and it was using the registry. I cleared the cache and disabled it in the client and I also added the following lines to my code:
$F25sessionOptions.AddRawSettings("Compression", "1")
$F25sessionOptions.AddRawSettings("CacheDirectories", "0")
$F25sessionOptions.AddRawSettings("CacheDirectoryChanges", "0")
The download time went from 48 minutes for 4.55 Gb to 11 minutes for 4.57 Gb.

If anyone else is trying to improve speed and the turning off of optimization doesn't do the trick, check your cache settings (especially if the performance degraded slowly over time).

As a side note, we did try the vendor's preferred application (MOVEit-EZ) and it was doing 11 min downloads, but it ran as a service and it crashed one night and I cannot afford to have it not run. My code has run for months without a failure so I'm sticking with it. ;)

Thanks again Martin .. these tools are awesome.

Reply with quote

martin
Site Admin
martin avatar

Re: Possible Solution .. Download Time is Now at 11 Minutes

Thanks for sharing your findings. Is your process long running? Because in .NET assembly, the caches are in-memory only. They are not written anywhere – not even to registry – or do you believe otherwise?

Reply with quote

corey.mcentyre
Donor
Joined:
Posts:
6
Location:
Norway, Maine

Re: Possible Solution .. Download Time is Now at 11 Minutes

Weird. Maybe I misunderstood this. The only item I found that sounded like something was being stored and possibly read each time was from this link:

[url]
https://winscp.net/eng/docs/directory_cache
[/url]

I saw the "Martin Prikryl" entry in the registry and *hoped* that clearing the cache and disabling it would result in faster performance if I eliminated the need to store and check every download permanently. It felt like a ridiculous long shot, but when it worked I thought I had found the key. :-/

The two sentences I placed my hope on were:

"The directory cache is updated whenever you perform any operation on the directory, like file transfer."

** and **

"The cache is enabled by default and can be disabled by unticking the Cache directory changes checkbox. The cache can be permanent (enabled by default), i.e. preserved between sessions. It is stored into configuration storage."

I've attached a session file from the 11 min run in case something jumps out. I can turn debug back on and see how she does if needed (I turned it off and removed the debug files once "solved" since I didn't want plain text versions of my password on the server - I should have kept them and blanked the PWs).

I also tried adjusting the SFTPDownloadQueue setting to 64, but it didn't speed it up - in fact, the download took 50 minutes so I removed that and will have to be happy at 11 minutes with the existing code unless there is a clear problem with my end of the configuration. :)

I've attached that session file as well in case there is something that jumps out as wrong on either end.

As always .. thanks for any advice / direction.
Description: Obfuscated Session File from run with SFTPDownloadQueue Set at 64
Description: Obfuscated Session file.

Reply with quote

corey.mcentyre
Donor
Joined:
Posts:
6
Location:
Norway, Maine

You were correct Martin (big surprise ;-) )

Martin ..

It looks as though my code change had no impact on the performance. It was simply a coincidence. The downloads are back at 45-50 minutes for 4.5Gb. I think I'm just going to live with it. I'll take reliability over speed any day. I have no idea why I got an 11 minute night or why its back at 45, but I'm just going to have to move my focus back to other projects. Thank you for your input and WinSCP education.

With gratitude ..
Corey

Reply with quote

Advertisement

You can post new topics in this forum