New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Progress bar can significantly impact cmdlet performance #2138

Closed
SteveL-MSFT opened this Issue Aug 30, 2016 · 27 comments

Comments

10 participants
@SteveL-MSFT
Copy link
Member

SteveL-MSFT commented Aug 30, 2016

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

This comment has been minimized.

Copy link

GeeLaw commented Aug 31, 2016

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

This comment has been minimized.

Copy link
Member Author

SteveL-MSFT commented Aug 31, 2016

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

This comment has been minimized.

Copy link

jasongin commented Oct 3, 2016

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.

@SteveL-MSFT SteveL-MSFT added this to the 6.0.0 milestone Oct 3, 2016

@jasongin

This comment has been minimized.

Copy link

jasongin commented Oct 4, 2016

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 SteveL-MSFT changed the title Invoke-webrequest slow at downloading files due to progress bar perf Progress bar can significantly impact cmdlet performance Oct 4, 2016

@SteveL-MSFT

This comment has been minimized.

Copy link
Member Author

SteveL-MSFT commented Oct 4, 2016

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

@Jaykul

This comment has been minimized.

Copy link

Jaykul commented Oct 7, 2016

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

This comment has been minimized.

Copy link
Contributor

oising commented Oct 18, 2016

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

This comment has been minimized.

Copy link
Collaborator

iSazonov commented Nov 2, 2016

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

This comment has been minimized.

Copy link
Contributor

oising commented Nov 2, 2016

@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

This comment has been minimized.

Copy link
Collaborator

iSazonov commented Nov 3, 2016

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

@iSazonov

This comment has been minimized.

Copy link
Collaborator

iSazonov commented Nov 3, 2016

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

This comment has been minimized.

Copy link
Member

lzybkr commented Nov 4, 2016

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

This comment has been minimized.

Copy link
Collaborator

iSazonov commented Nov 5, 2016

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

@daxian-dbw

This comment has been minimized.

Copy link
Member

daxian-dbw commented Nov 30, 2016

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.

@daxian-dbw daxian-dbw reopened this Nov 30, 2016

@iSazonov

This comment has been minimized.

Copy link
Collaborator

iSazonov commented Nov 30, 2016

@daxian-dbw
Maybe:
1.The timer set up a new _progPaneUpdateFlag
2. 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

This comment has been minimized.

Copy link
Collaborator

iSazonov commented Nov 30, 2016

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

This comment has been minimized.

Copy link
Collaborator

iSazonov commented Nov 30, 2016

@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

This comment has been minimized.

Copy link
Collaborator

iSazonov commented Mar 18, 2017

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

@SteveL-MSFT

This comment has been minimized.

Copy link
Member Author

SteveL-MSFT commented Mar 18, 2017

@iSazonov using same repro as above

With alpha.17:

TotalSeconds      : 65.3537138

with your fix:

TotalSeconds      : 10.9945305

Looks good!

@iSazonov

This comment has been minimized.

Copy link
Collaborator

iSazonov commented Mar 19, 2017

Great! Many thanks to @daxian-dbw!

@daxian-dbw

This comment has been minimized.

Copy link
Member

daxian-dbw commented Mar 20, 2017

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

@joeyaiello joeyaiello added this to Completed in Linux/Mac Usability Mar 20, 2017

@NiclasLindgren

This comment has been minimized.

Copy link

NiclasLindgren commented Jul 12, 2017

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

This comment has been minimized.

Copy link
Collaborator

iSazonov commented Jul 12, 2017

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

@NiclasLindgren

This comment has been minimized.

Copy link

NiclasLindgren commented Jul 12, 2017

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

This comment has been minimized.

Copy link
Collaborator

iSazonov commented Jul 13, 2017

@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

This comment has been minimized.

Copy link
Contributor

oising commented Jul 13, 2017

@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

This comment has been minimized.

Copy link
Member Author

SteveL-MSFT commented Jul 13, 2017

@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

@SteveL-MSFT SteveL-MSFT moved this from Completed to Done in Linux/Mac Usability Mar 18, 2018

natemcmaster added a commit to aspnet/AspNetCore that referenced this issue Jan 11, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment