Powershell: Progress bar can significantly impact cmdlet performance

[SteveL-MSFT]

Repro Steps :

Compare perf of WebClient, BITS and Invoke-WebRequest:

Measure-Command { $wc = New-Object System.Net.WebClient; $wc.DownloadFile("https://github.com/dotnet/corefx/archive/master.zip", "C:\Users\crispop\Desktop\master.zip") }


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 3
Milliseconds      : 992
Ticks             : 39928426
TotalDays         : 4.62134560185185E-05
TotalHours        : 0.00110912294444444
TotalMinutes      : 0.0665473766666667
TotalSeconds      : 3.9928426
TotalMilliseconds : 3992.8426
Vs

Measure-Command { Invoke-WebRequest "https://github.com/dotnet/corefx/archive/master.zip" -OutFile "C:\Users\crispop\Desktop\master.zip" }


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 50
Milliseconds      : 821
Ticks             : 508212825
TotalDays         : 0.000588209288194444
TotalHours        : 0.0141170229166667
TotalMinutes      : 0.847021375
TotalSeconds      : 50.8212825
TotalMilliseconds : 50821.2825

Vs

Measure-Command { Start-BitsTransfer -Source "https://github.com/dotnet/corefx/archive/master.zip" -Destination "C:\Users\crispop\Desktop\masterBits2.zip" }


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 4
Milliseconds      : 506
Ticks             : 45062594
TotalDays         : 5.21557800925926E-05
TotalHours        : 0.00125173872222222
TotalMinutes      : 0.0751043233333333
TotalSeconds      : 4.5062594
TotalMilliseconds : 4506.2594

Expected: Transfer speeds don't differ too much (maybe Invoke-WebRequest should be a bit faster than BITS which performs the transfer in background.)

Actual: 10x slowdown for Invoke-WebRequest

[GeeLaw]

How can you be sure that it's the progress bar? With $ProgressPreference = 'SilentlyContinue', you can suppress the progress bar UI, which will surely boost Invoke-WebRequest. Also, use -UseBasicParsing when downloading files with iwr (which you shouldn't do since that's not what iwr is for...). You cannot suppress parsing, but you can suppress DOM parsing.

Moreover, I did your tests and found that the standard deviation is rather great (poor network here in China).

Please do observe Task Manager for the network speed and also do more statistics. If the network is perfect (I hosted a file locally and tried to download via localhost, all three were superfast even the file is 80MB+, with progress bar suppressed.)

And, could you include the $PSVersionTable?

[SteveL-MSFT]

PSEdition Core
CLRVersion
PSCompatibleVersions {1.0, 2.0, 3.0, 4.0...}
BuildVersion 3.0.0.0
GitCommitId v6.0.0-alpha.9
PSRemotingProtocolVersion 2.3
PSVersion 6.0.0-alpha
WSManStackVersion 3.0
SerializationVersion 1.1.0.1

[jasongin]

I also see the progress bar slowing down Invoke-WebRequest by >50X on a fast internet connection. Every time I write a script that uses Invoke-WebRequest I need to include code to temporarily change $ProgressPreference, then restore it later (because I do want progress for other things).

Here's my output from using Invoke-WebRequest to download the same file as @SteveL-MSFT, without and then with progress:

PS D:\> $ProgressPreference = 'SilentlyContinue'
PS D:\> Measure-Command { Invoke-WebRequest "https://github.com/dotnet/corefx/archive/master.zip" -OutFile "D:\temp\master.zip" }

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 6
Milliseconds      : 72
Ticks             : 60729893
TotalDays         : 7.02892280092593E-05
TotalHours        : 0.00168694147222222
TotalMinutes      : 0.101216488333333
TotalSeconds      : 6.0729893
TotalMilliseconds : 6072.9893

PS D:\> $ProgressPreference = 'Continue'
PS D:\> Measure-Command { Invoke-WebRequest "https://github.com/dotnet/corefx/archive/master.zip" -OutFile "D:\temp\master2.zip" }

Days              : 0
Hours             : 0
Minutes           : 6
Seconds           : 11
Milliseconds      : 664
Ticks             : 3716642777
TotalDays         : 0.00430166988078704
TotalHours        : 0.103240077138889
TotalMinutes      : 6.19440462833333
TotalSeconds      : 371.6642777
TotalMilliseconds : 371664.2777

PS D:\> $PSVersionTable

Name                           Value
----                           -----
PSVersion                      5.1.14931.1000
PSEdition                      Desktop
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0...}
BuildVersion                   10.0.14931.1000
CLRVersion                     4.0.30319.42000
WSManStackVersion              3.0
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1

It would be nice to be able to have reasonable progress when downloading a file. Perhaps if there were a way to adjust the progress reporting interval to several KB instead of every byte (!!) then the overhead wouldn't be so bad.

[jasongin]

This issue also affects Expand-Archive. For a large archive (10 MB with 3495 files), expanding it takes over 4X long with progress compared to without.

[SteveL-MSFT]

Changed title to be a generic issue with the progress bar.

[Jaykul]

Yeah, this is pretty bad ...

  Duration CommandLine
  -------- -----------
0.0356085s 1..1e3 | % { $null }
0.7734768s 1..1e3 | % { Write-Host "..." }
4.8700151s 1..1e3 | % { Write-Progress "..." }
0.0040193s $ProgressPreference = "SilentlyContinue"
0.0573198s 1..1e3 | % { Write-Progress "..." }

[oising]

I remember noticing how much of a blocker progress writing was when I wrote the PSCX GAC provider back in 2007:

            foreach (AssemblyName name in Fusion.GetAssemblies(_type))
            {
                ++i;

                if (i % 5 == 0)
                {
                    WriteProgress(name.Name);
                }

https://github.com/Pscx/Pscx/blob/master/Src/Pscx/Providers/AssemblyCache/AssemblyNameCache.cs#L79

We decided to only write a record on every fifth iteration.

[iSazonov]

It's very simple (write a record on every fifth iteration). 👍 Just seems the compromise is not always the optimal.
May be possible to write asynchronously every 3-5 seconds?

[oising]

@iSazonov Yeah. I'm just saying that it's a problem that's been there since the beginning. Skipping records doesn't solve all issues.

[iSazonov]

@oising This is not a criticism from me. I just asked your opinion on "async" since you have experience with the problem.

[iSazonov]

I did some research in codes and found that a partial solution already exists in Checkpoint-Computer

            if (recordType == ProgressRecordType.Processing)
            {
                TimeSpan timeSinceProgressWasWrittenLast = DateTime.UtcNow - lastTimeProgressWasWritten;
                if (timeSinceProgressWasWrittenLast < TimeSpan.FromMilliseconds(200))
                {
                    return;
                }
            }
            lastTimeProgressWasWritten = DateTime.UtcNow;

I used this for the test. Working call chain for WriteProgress is cmdlet.cs -> MshCommandRuntime.cs -> InternalHostUserInterface.cs -> ConsoleHostUserInterface.cs -> ConsoleHostUserInterfaceProgress.cs

In HandleIncomingProgressRecord (ConsoleHostUserInterfaceProgress.cs) I "mask" _progPane.Show(_pendingProgress);

            TimeSpan timeSinceProgressWasWrittenLast = DateTime.UtcNow - _lastTimeProgressWasWritten;
            if (timeSinceProgressWasWrittenLast > TimeSpan.FromMilliseconds(200))
            {
                _progPane.Show(_pendingProgress);
                _lastTimeProgressWasWritten = DateTime.UtcNow;
            }

Performance tests have shown that after this change, the difference between SilentlyContinue and Continue is less 3%.

I played with TimeSpan.FromMilliseconds(200)) and found that this value is optimal.
TimeSpan.FromMilliseconds(500)) is not giving a improvement, but the display becomes noticeably discrete.

If this is the correct place for the patch, I can do PR.

@daxian-dbw @lzybkr Could you comment please?

[lzybkr]

That's an interesting idea, I use a similar hack in PSReadline to minimize rendering calls.

There is one big problem with this approach - if we skip an update and don't see any progress updates for a long time, the current "hung" state would be misleading because the last update wasn't rendered.

If we could render updates on a timer, that might be ideal.

[iSazonov]

@lzybkr Thanks for comment!
I agree completely, and I will do the patch to call _progPane.Show(_pendingProgress); on a timer.

[daxian-dbw]

It turns out the timer fix causes some potential race conditions (see the issue #2800 and discussions in PR #2771). So the timer change was reverted with PR #2806 for now, and we need to different approach to address this problem.

It would be very helpful if someone can run a profiler on Invoke-WebRequest to get more accurate data for analysis.

[iSazonov]

@daxian-dbw
Maybe:
1.The timer set up a new _progPaneUpdateFlag

1. HandleIncomingProgressRecord check `_progPaneUpdateFlag then call _progPane.Show(_pendingProgress) and reset the _progPaneUpdateFlag

It seems that we can simply control the time delta in HandleIncomingProgressRecord , but my earlier tests showed that is significantly slower.

[iSazonov]

From @daxian-dbw

@iSazonov That is an interesting proposal -- by doing all the work in the same thread we certainly can avoid all race conditions. However, if Write-Progress is not called very frequently, then it's possible that the progress bar will not be updated ( Show will not be called) for a long time.
Let's move this discussion to the issue, so more people can jump in 😄

[iSazonov]

@daxian-dbw

However, if Write-Progress is not called very frequently, then it's possible that the progress bar will not be updated ( Show will not be called) for a long time.

The hung problem was not full resolved by my PR too because Write-Progress is not called very frequently . The PR solved only a performance problem. I planned to solve this problem in a subsequent PR.

Actually there are three problems in one place, which might require different solutions:

1. Calling HandleIncomingProgressRecord too often leads to unnecessary rendering. There is no need to update the pane structures so often and consume unnecessary resources. My above proposal I believe is good enough to protect from this. (We should not simply slow down rendering e.g. when calling Now() and checking the time delta because the script should continue to work as quickly as possible.)
2. Hung or Freeze of a progress pane. If Write-Progress is not called very frequently user sees that the pane freeze. It may be a good solution to display a indicator updated by the same or other timer. It is better for UX to see the changes on the screen for long scripts.
3. If Write-Progress show a progress pane and the script make output to console the user sees that the display shatters. These two processes should be "merged" to form a single buffer for display.

[iSazonov]

@SteveL-MSFT Can you confirm that now web cmdlets performance is better with progress bar?

[SteveL-MSFT]

@iSazonov using same repro as above

With alpha.17:

TotalSeconds      : 65.3537138

with your fix:

TotalSeconds      : 10.9945305

Looks good!

[iSazonov]

Great! Many thanks to @daxian-dbw!

[daxian-dbw]

@iSazonov thank you for pushing the fix through!
There are 3 minor remaining issues and they are tracked by #3366

[NiclasLindgren]

Not sure if it is of interest still, but the speed when run under ISE instead of console is about the same as running command without progress. So the ISE console does not exhibit the same issue, or different buffering is used

[iSazonov]

@NiclasLindgren Thanks for your comment!
ISE is not in the PowerShell Core repo, it is not ported and no plans is.

[NiclasLindgren]

Yes, my point was, that "powershell for windows" (v4.0) has the same problem, When run under ISE the "console" does not slow down the performance, I thought it might be interesting for those with access to ISE to check what they do. Either way, the solution discussed here helped and I am happy =)

[iSazonov]

@NiclasLindgren Welcome to test PowerShell Core Beta.4! We have some console fixes in last time from @lzybkr so you may be surprised how much the console is faster. Also we wait a feedback for loading and using Windows PowerShell modules in PowerShell Core Beta.4.

[oising]

@niclaslindgren the long and short of it is that rendering progress bars in WPF is orders of magnitude fast than drawing progress bars in the windows console. It's not about the code path per-se.

[SteveL-MSFT]

@NiclasLindgren haven't peeked at the ISE code, but I suspect the progress bar is being rendered on a separate thread while the console uses the same thread