Powershell: Command discovery on systems with symlinks to slow filesystems is slow
Not all commands. ls takes 20 seconds. dir is nearly instant. This is just the simplest example, but the overall experience makes me want to stop using powershell on Linux. :-( Tab completion also takes around 20 seconds.
Steps to reproduce
PS > measure-command { ls }
Days : 0
Hours : 0
Minutes : 0
Seconds : 20
Milliseconds : 25
Ticks : 200252179
TotalDays : 0.000231773355324074
TotalHours : 0.00556256052777778
TotalMinutes : 0.333753631666667
TotalSeconds : 20.0252179
TotalMilliseconds : 20025.2179
PS > measure-command { dir }
Days : 0
Hours : 0
Minutes : 0
Seconds : 0
Milliseconds : 3
Ticks : 33095
TotalDays : 3.83043981481481E-08
TotalHours : 9.19305555555556E-07
TotalMinutes : 5.51583333333333E-05
TotalSeconds : 0.0033095
TotalMilliseconds : 3.3095
Expected behavior
ls takes a second or so.
Actual behavior
ls takes 20 seconds.
Environment data
> $PSVersionTable
Name Value
---- -----
PSVersion 6.1.0-preview.1
PSEdition Core
GitCommitId v6.1.0-preview.1
OS Linux 4.9.0-6-amd64 #1 SMP Debian 4.9.82-1+deb9u3 (2018-03-02)
Platform Unix
PSCompatibleVersions {1.0, 2.0, 3.0, 4.0...}
PSRemotingProtocolVersion 2.3
SerializationVersion 1.1.0.1
WSManStackVersion 3.0
SurferJeffAtGoogle
All 29 comments
@SurferJeffAtGoogle Can you run Get-Command ls and Get-Command dir to see what commands are actually being executed? We don't install the "ls -> Get-ChildItem" alias on Linux by default so you should just be running the native /bin/ls (or whatever's in your path). We do ship the "dir->Get-ChildItem" alias but you say that's OK which is confusing.
BrucePay
on 6 Apr 2018
What's surprising is that calling get-command ls also takes 20 seconds!
PS > get-command ls
CommandType Name Version Source
----------- ---- ------- ------
Application ls 0.0.0.0 /bin/ls
PS > get-command dir
CommandType Name Version Source
----------- ---- ------- ------
Alias dir -> Get-ChildItem
PS > measure-command { get-command ls }
Days : 0
Hours : 0
Minutes : 0
Seconds : 20
Milliseconds : 35
Ticks : 200359003
TotalDays : 0.000231896994212963
TotalHours : 0.00556552786111111
TotalMinutes : 0.333931671666667
TotalSeconds : 20.0359003
TotalMilliseconds : 20035.9003
But with a bash shell, the equivalent of get-command takes hardly any time:
$ which ls
/bin/ls
$ time which ls
/bin/ls
real 0m0.003s
user 0m0.000s
sys 0m0.000s
I have experiencing the same issue sporadically in both Windows and Linux. Sometimes is fast and other time slow.
(?)
MaximoTrinidad
on 6 Apr 2018
@SurferJeffAtGoogle What happens when you launch ls with a fully qualified path
/bin/ls
Also, can you try other executables like true
true
/bin/true
Finally, what does your path look like in PowerShell
$ENV:PATH
If it's mangled, then that would explain both slow launching and slow Get-Command calls.
BrucePay
on 6 Apr 2018
Launching with the full path runs quick:
PS > measure-command { ls }
Days : 0
Hours : 0
Minutes : 0
Seconds : 20
Milliseconds : 62
Ticks : 200625091
TotalDays : 0.000232204966435185
TotalHours : 0.00557291919444444
TotalMinutes : 0.334375151666667
TotalSeconds : 20.0625091
TotalMilliseconds : 20062.5091
PS > measure-command { /bin/ls }
Days : 0
Hours : 0
Minutes : 0
Seconds : 0
Milliseconds : 6
Ticks : 66497
TotalDays : 7.69641203703704E-08
TotalHours : 1.84713888888889E-06
TotalMinutes : 0.000110828333333333
TotalSeconds : 0.0066497
TotalMilliseconds : 6.6497
PS > measure-command { true }
Days : 0
Hours : 0
Minutes : 0
Seconds : 20
Milliseconds : 30
Ticks : 200306653
TotalDays : 0.000231836403935185
TotalHours : 0.00556407369444444
TotalMinutes : 0.333844421666667
TotalSeconds : 20.0306653
TotalMilliseconds : 20030.6653
PS > measure-command { /bin/true }
Days : 0
Hours : 0
Minutes : 0
Seconds : 0
Milliseconds : 15
Ticks : 155612
TotalDays : 1.80106481481481E-07
TotalHours : 4.32255555555556E-06
TotalMinutes : 0.000259353333333333
TotalSeconds : 0.0155612
TotalMilliseconds : 15.5612
Here's my path. It's identical in bash, and bash does not experience the same slowness.
PS /usr/local/google/home/rennie/tmp> ls
PS /usr/local/google/home/rennie/tmp> /bin/ls
PS /usr/local/google/home/rennie/tmp> $env:PATH
/opt/microsoft/powershell/6.1.0~preview.1:/usr/local/google/home/rennie/Downloads/google-cloud-sdk/bin:/usr/local/google/home/rennie/Downloads/phantomjs-1.9.8-linux-x86_64/bin:/usr/local/google/home/rennie/.composer/vendor/bin:/usr/local/google/home/rennie/bin:/usr/local/google/home/rennie/.phpenv/bin:/usr/local/google/home/rennie/Downloads/dotnet-2.0.5:/usr/local/google/home/rennie/Downloads/dotnet-1.1.2:/usr/local/google/home/rennie/Downloads/apache-maven-3.3.9/bin:/usr/local/google/home/rennie/Downloads/node-v4.2.1-linux-x64/bin:/usr/local/google/home/rennie/Downloads/google-cloud-sdk/bin:/usr/local/google/home/rennie/.composer/vendor/bin:/usr/local/google/home/rennie/bin:/usr/local/google/home/rennie/.phpenv/bin:/usr/local/google/home/rennie/Downloads/dotnet-2.0.5:/usr/local/google/home/rennie/Downloads/dotnet-1.1.2:/usr/local/google/home/rennie/Downloads/apache-maven-3.3.9/bin:/usr/local/google/home/rennie/Downloads/node-v4.2.1-linux-x64/bin:/usr/lib/google-golang/bin:/usr/local/buildtools/java/jdk/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
PS /usr/local/google/home/rennie/tmp>
rennie@rennie:~/tmp$
rennie@rennie:~/tmp$ env | grep ^PATH
PATH=/usr/local/google/home/rennie/Downloads/google-cloud-sdk/bin:/usr/local/google/home/rennie/Downloads/phantomjs-1.9.8-linux-x86_64/bin:/usr/local/google/home/rennie/.composer/vendor/bin:/usr/local/google/home/rennie/bin:/usr/local/google/home/rennie/.phpenv/bin:/usr/local/google/home/rennie/Downloads/dotnet-2.0.5:/usr/local/google/home/rennie/Downloads/dotnet-1.1.2:/usr/local/google/home/rennie/Downloads/apache-maven-3.3.9/bin:/usr/local/google/home/rennie/Downloads/node-v4.2.1-linux-x64/bin:/usr/local/google/home/rennie/Downloads/google-cloud-sdk/bin:/usr/local/google/home/rennie/.composer/vendor/bin:/usr/local/google/home/rennie/bin:/usr/local/google/home/rennie/.phpenv/bin:/usr/local/google/home/rennie/Downloads/dotnet-2.0.5:/usr/local/google/home/rennie/Downloads/dotnet-1.1.2:/usr/local/google/home/rennie/Downloads/apache-maven-3.3.9/bin:/usr/local/google/home/rennie/Downloads/node-v4.2.1-linux-x64/bin:/usr/lib/google-golang/bin:/usr/local/buildtools/java/jdk/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
rennie@rennie:~/tmp$
Even when I reduce my path to almost nothing, the performance is similar:
PS /usr/local/google/home/rennie/tmp> $env:PATH
$env:PATH
/opt/microsoft/powershell/6.1.0~preview.1:/usr/bin
PS /usr/local/google/home/rennie/tmp> measure-command { ls }
ls : The term 'ls' is not recognized as the name of a cmdlet, function, script file, or operable program.
Check the spelling of the name, or if a path was included, verify that the path is correct and try again.
At line:1 char:19
+ measure-command { ls }
+ ~~
+ CategoryInfo : ObjectNotFound: (ls:String) [], CommandNotFoundException
+ FullyQualifiedErrorId : CommandNotFoundException
Days : 0
Hours : 0
Minutes : 0
Seconds : 40
Milliseconds : 122
Ticks : 401220615
TotalDays : 0.000464375711805556
TotalHours : 0.0111450170833333
TotalMinutes : 0.668701025
TotalSeconds : 40.1220615
TotalMilliseconds : 40122.0615
PS /usr/local/google/home/rennie/tmp> measure-command { /bin/ls }
Days : 0
Hours : 0
Minutes : 0
Seconds : 0
Milliseconds : 14
Ticks : 141501
TotalDays : 1.63774305555556E-07
TotalHours : 3.93058333333333E-06
TotalMinutes : 0.000235835
TotalSeconds : 0.0141501
TotalMilliseconds : 14.1501
PS /usr/local/google/home/rennie/tmp>
@SurferJeffAtGoogle Is this still an issue with 6.2?
SteveL-MSFT
on 23 Mar 2019
I haven't tried 6.2 yet:
PS /usr/local/google/home/rennie> $PSVersionTable.PSVersion
Major Minor Patch PreReleaseLabel BuildLabel
6 1 3
PS /usr/local/google/home/rennie> measure-command { clear }
Days : 0
Hours : 0
Minutes : 0
Seconds : 14
Milliseconds : 249
Ticks : 142493659
TotalDays : 0.000164923216435185
TotalHours : 0.00395815719444444
TotalMinutes : 0.237489431666667
TotalSeconds : 14.2493659
TotalMilliseconds : 14249.3659
On Sat, Mar 23, 2019 at 12:06 PM Steve Lee notifications@github.com wrote:
@SurferJeffAtGoogle https://github.com/SurferJeffAtGoogle Is this still
an issue with 6.2?—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/PowerShell/PowerShell/issues/6577#issuecomment-475896182,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ALO54srnStQZaWiQRpKutZjzkwd1KVeLks5vZns3gaJpZM4TJN34
.
SurferJeffAtGoogle
on 25 Mar 2019
@SurferJeffAtGoogle I setup a new Debian 9 VM on my macBook Pro. Installed 6.1.3, and executed:
measure-command { clear }
That finished in 46ms
SteveL-MSFT
on 25 Mar 2019
I suspect my corp environment has some quirks that don't exist elsewhere.
Is there a tool I can run to trace where PowerShell is spending its time?
On Mon, Mar 25, 2019 at 11:27 AM Steve Lee notifications@github.com wrote:
@SurferJeffAtGoogle https://github.com/SurferJeffAtGoogle I setup a new
Debian 9 VM on my macBook Pro. Installed 6.1.3, and executed:measure-command { clear }
That finished in 46ms
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/PowerShell/PowerShell/issues/6577#issuecomment-476322368,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ALO54iKThLfzku3XDHnNqrJg21avv2nWks5vaRUHgaJpZM4TJN34
.
SurferJeffAtGoogle
on 25 Mar 2019
Would you be able to clone my branch from https://github.com/PowerShell/PowerShell/pull/9230 which adds timestamps to the trace command and do this:
trace-command -Name * -Expression { true } -PSHost
And see where it's spending its time?
SteveL-MSFT
on 26 Mar 2019
Thank you. I'll try that. But it could take a few days due to my other
commitments.
On Tue, Mar 26, 2019 at 11:22 AM Steve Lee notifications@github.com wrote:
Would you be able to clone my branch from #9230
https://github.com/PowerShell/PowerShell/pull/9230 which adds
timestamps to the trace command and do this:trace-command -Name * -Expression { true } -PSHost
And see where it's spending its time?
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/PowerShell/PowerShell/issues/6577#issuecomment-476784404,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ALO54t30ivILSl7Yc95tMSSjBCra0SuRks5vamVNgaJpZM4TJN34
.
SurferJeffAtGoogle
on 27 Mar 2019
@SurferJeffAtGoogle Thanks! No rush, not much we can do for 6.2 right now anyways.
SteveL-MSFT
on 27 Mar 2019
Fellow Googler here, with similar corp setup.
The problem seems to be that we have symlinks in /usr/bin, pointing to files on slow filesystems. In zsh I can see ls --color=never /usr/bin is instant but ls ---color=always /usr/bin takes seconds (presumably resolving symlinks to print them in them red if invalid). I can confirm by looking at trace-command output that the time is spent "looking for true in /usr/bin" and removing /usr/bin from $env:PATH fixes the issue.
bendowski
on 23 Aug 2019
Thank you @bendowski! That helps.
SurferJeffAtGoogle
on 24 Aug 2019
I see this as a pain point, but this seems to do with the filesystem perf and not something PowerShell can do without someone coming up with a proposal
SteveL-MSFT
on 15 Oct 2019
For the record: other shells (bash, zsh) work fine in this setup. I can only guess they don't check the executable bit (or other file attributes) ahead of time for every file on the PATH, only when needed to actually run a binary.
bendowski
on 16 Oct 2019
@bendowski ok, that's something we could potentially do as an optimization!
SteveL-MSFT
on 16 Oct 2019
We look files by paths from PATH environment variable and by executable extentions in https://github.com/PowerShell/PowerShell/blob/48db3de03ed427f10646f1fbb824a2b4eb958378/src/System.Management.Automation/engine/CommandPathSearch.cs#L408
We could try new API FileSystemEnumerable() in the method where we can use custom predicate to filter files in directory but it is another scenario (Suggestions, or FuzzyMatch).
Also we see possible perf issue in the algorithm. We use search pattern like "ping.exe." and then the same for all extensions - "ping.exe.ps1", "ping.exe.cpl" and so on, but it seems the first pattern overlaps the follow ones: if we do not find first then it makes no sense check rest.
iSazonov
on 16 Oct 2019
@SteveL-MSFT If I remember correctly PATHEXT is only for Windows. So
there is no need to check extensions on Unix-s, right?
iSazonov
on 17 Oct 2019
@SteveL-MSFT We have a perf regression on Windows. For Get-Command ping __~3 ms__ on my system.
Test script:
for ($i=0; $i -lt 2000; $i++) {
Get-Command ping > $null
}
On Windows PowerShell 5.1 and up to PowerShell Core 6.1.0-Preview2 I get __~2.5 sec__.
Starting with PowerShell Core 6.1.0-Preview2 I get __~8.2 sec__.
I compare traces for PowerShell Core 6.1.0-Preview2 and PowerShell Core 6.1.0-Preview3
You can see that there other P/Invokes are used in Preview3.
I guess it was a change in .Net Core. If so I guess they know about this and accepted consciously.
Should we worry about this or can we ignore it?
Update: Maybe on Unix we have have the same root of the regression?
iSazonov
on 17 Oct 2019
@iSazonov yes, PATHEXT is a Windows only thing. On non-Windows, the executable bit is what is interesting although we special case .ps1. The perf data is different from what this issue is discussing which is specific to traversing symlinks opening files at discovery time rather than at runtime.
SteveL-MSFT
on 17 Oct 2019
@SteveL-MSFT Thanks! Clear about PATHEXT.
My trace is for discovery code. I think just the enumeration (Directory.EnumerateFiles()) is slow, not exec bit check.
Our exec bit check is _on last step_ for single file (after we enumerate all files in a directory and filter by name) so if we remove them it does not help.
iSazonov
on 18 Oct 2019
@bendowski @SurferJeffAtGoogle Please download compiled artifact from #10815 and look if you see any perf change.
iSazonov
on 18 Oct 2019
@iSazonov Can you open a corefx issue about Directory.EnumerateFiles()? That perf regression is really bad and not expected.
0xd4d
on 18 Oct 2019
@0xd4d PowerShell repo steps is not useful for Core team. This requires a C# repo. I didn't have time to check it out (on different .Net Core versions).
iSazonov
on 18 Oct 2019
@iSazonov I opened a corefx issue about that problem https://github.com/dotnet/corefx/issues/41898
0xd4d
on 18 Oct 2019
I'm sorry for the delay. I tried the build you linked as well as the latest preview (7.0.0-preview5) and they seem to behave the same. It's much better than before (with ls taking 20 seconds), but still some commands take longer than I would expect. This seems to be somewhat non-deterministic, see this example of running "true" 4 times in a row:
PS /> measure-command { true }
Days : 0
Hours : 0
Minutes : 0
Seconds : 0
Milliseconds : 28
Ticks : 289087
TotalDays : 3.34591435185185E-07
TotalHours : 8.03019444444444E-06
TotalMinutes : 0.000481811666666667
TotalSeconds : 0.0289087
TotalMilliseconds : 28.9087
PS /> measure-command { true }
Days : 0
Hours : 0
Minutes : 0
Seconds : 0
Milliseconds : 443
Ticks : 4435776
TotalDays : 5.134E-06
TotalHours : 0.000123216
TotalMinutes : 0.00739296
TotalSeconds : 0.4435776
TotalMilliseconds : 443.5776
PS /> measure-command { true }
Days : 0
Hours : 0
Minutes : 0
Seconds : 0
Milliseconds : 34
Ticks : 346932
TotalDays : 4.01541666666667E-07
TotalHours : 9.637E-06
TotalMinutes : 0.00057822
TotalSeconds : 0.0346932
TotalMilliseconds : 34.6932
PS /> measure-command { true }
Days : 0
Hours : 0
Minutes : 0
Seconds : 0
Milliseconds : 422
Ticks : 4221326
TotalDays : 4.88579398148148E-06
TotalHours : 0.000117259055555556
TotalMinutes : 0.00703554333333333
TotalSeconds : 0.4221326
TotalMilliseconds : 422.1326
Doing the same with trace-command confirms the additional ~400ms is spent in /usr/bin:
DEBUG: 2019-10-24 13:53:38.2773 CommandDiscovery Information: 0 : Looking for true.ps1 in /usr/sbin
DEBUG: 2019-10-24 13:53:38.2784 CommandSearch Information: 0 : WriteLine Current directory results are invalid
DEBUG: 2019-10-24 13:53:38.2785 CommandSearch Information: 0 : WriteLine Current patterns exhausted in current directory: /usr/sbin
DEBUG: 2019-10-24 13:53:38.2785 CommandDiscovery Information: 0 : Looking for true in /usr/bin
DEBUG: 2019-10-24 13:53:38.6796 CommandSearch Information: 0 : WriteLine Current directory results are invalid
DEBUG: 2019-10-24 13:53:38.6798 CommandDiscovery Information: 0 : Looking for true.ps1 in /usr/bin
DEBUG: 2019-10-24 13:53:38.6914 CommandSearch Information: 0 : WriteLine Current directory results are invalid
DEBUG: 2019-10-24 13:53:38.6914 CommandSearch Information: 0 : WriteLine Current patterns exhausted in current directory: /usr/bin
Would love to see if someone could reproduce this one again on .NET 5 with the latest version of Win10. I know a ton of work has been done around filesystem access and symlinks in both of those products.
joeyaiello
on 21 Jul 2020
Related issues
pcgeek86
·
3Comments
HumanEquivalentUnit
·
3Comments
abock
·
3Comments
lzybkr
·
3Comments
rudolfvesely
·
3Comments
Most helpful comment
@iSazonov I opened a corefx issue about that problem https://github.com/dotnet/corefx/issues/41898