Powershell: Specifying a Set-Alias in your PowerShell profile causes startup time to significantly increase

[antiufo]

Steps to reproduce

Add the following line to an otherwise empty $profile file, and launch pwsh:

Set-Alias example dir

Expected behavior

PowerShell still loads reasonably fast.

Actual behavior

PowerShell loads considerably more slowly:

Loading personal and system profiles took 2026ms.

Get-Module shows that Microsoft.PowerShell.Utility is loaded when Set-Alias is used.

Given that aliases are one of the basic features you can expect users might want to customize in their profile, it seems unfortunate that doing so introduces such a significant slowdown.

Environment data

Name                           Value
----                           -----
PSVersion                      7.0.0-preview.4
PSEdition                      Core
GitCommitId                    7.0.0-preview.4
OS                             Linux 4.19.37-5+deb10u2rodete2-amd64 #1 SMP Debian 4.19.37-5+deb10u2rodete2 (2019-08-28 > 2018)
Platform                       Unix
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0…}
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1
WSManStackVersion              3.0

[kilasuit]

Is this if Set-Alias example dir is the only thing in your profile or do you have more things in your profile?

[antiufo]

My original PowerShell profile was longer, but after investigating what was causing the slowdown, I saw that using that single Set-Alias line was enough to make startup performance much worse (compared to an empty profile, or a profile that only calls commands that don't live in Microsoft.PowerShell.Utility)

[mklement0]

While startup time is generally a concern for PowerShell, it is most important in _non-interactive_ scenarios: CLI-based execution with -File or -Command.

For predictability, it is best to use -NoProfile in these cases, which bypasses loading of the profiles.
(Sadly, unlike POSIX-like shells, Powershell by default loads its profiles even when -File or -Command are used - see https://github.com/PowerShell/PowerShell/issues/8072 and https://github.com/PowerShell/PowerShell/issues/992#issuecomment-334965306 for the backstory )

In _interactive_ use, where you do want profiles loaded, the slowdown is noticeable, but doesn't strike me as dramatic; e.g.:

PS> { pwsh -nop -c 'get-module' }, { pwsh -nop -c 'set-alias a b; get-module'} | % { (Measure-Command $_).TotalSeconds }

0.472155
0.6102869

That is, the implicit loading of the Microsoft.PowerShell.Utility module triggered by the Set-Alias call (plus the Set-Alias call itself) increased the startup time by about 30% on my macOS 10.15 machine.

Given how many basic cmdlets live in said module, it's quite likely that the average profile triggers its import - and once it is imported, using other commands from it doesn't cause additional delays.

[antiufo]

I see. I still wonder why the loading of such a common/core module incurs in such a significant time penalty.

PS> 1..10 | % { (Measure-Command { pwsh -nop -c 'get-module' }).TotalSeconds }
0.3870604
0.3874905
0.3915055
0.3906345
0.3659332
0.3865723
0.3756553
0.3879174
0.3707061
0.3833163

PS> 1..10 | % { (Measure-Command { pwsh -nop -c 'set-alias a b; get-module' }).TotalSeconds }
3.0328228
0.5088773
1.0092562
1.8483153
0.4995922
0.503561
2.1008697
0.4854821
0.4657199
1.5687297

By comparison, a simple
[Reflection.Assembly]::Load('Microsoft.PowerShell.Commands.Management') (needed by Get-Location), or ::Load('Microsoft.PowerShell.Commands.Utility') (needed by Set-Alias) completes almost immediately.

[mklement0]

@antiufo

Generally, importing a module involves more than just loading an assembly, but hopefully someone more familiar with the module-loading infrastructure can elaborate on what exactly is involved and whether there is potential for improving the current performance.

As for your 2nd measurement command: These measurements look erratic to me - I don't see the same fluctuations and performance gap, neither on macOS nor on Windows - was your machine just busy at the time, or can you reproduce this? What OS? What PS version?

[antiufo]

I checked with strace.
The time is spent enumerating /usr/bin, /usr/sbin and stat()-ing each of the files they contain.
Some entries fail with timeout errors, possibly because they're links to remote filesystems.

strace -f -tt -o trace.txt pwsh -noprofile -c '[IO.File]::WriteAllText("/tmp/BEFORE.txt", 1);set-alias a b;[IO.File]::WriteAllText("/tmp/AFTER.txt", 2)'

Somewhere between BEFORE and AFTER, I can find a long sequence like this in trace.txt:

176008 14:02:50.154366 stat("/usr/bin/pdb", {st_mode=S_IFREG|0755, st_size=46098, ...}) = 0
176008 14:02:50.154415 stat("/usr/bin/compare", {st_mode=S_IFREG|0755, st_size=14520, ...}) = 0
176008 14:02:50.154464 stat("/usr/bin/f", {st_mode=S_IFREG|0755, st_size=30385816, ...}) = 0
176008 14:02:50.154519 stat("/usr/bin/jade",  <unfinished ...>
175956 14:02:50.242165 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
175956 14:02:50.242241 futex(0x22be7f0, FUTEX_WAKE_PRIVATE, 1) = 0
175956 14:02:50.242310 futex(0x2477924, FUTEX_WAKE_PRIVATE, 1) = 1
175957 14:02:50.242350 <... futex resumed> ) = 0
175956 14:02:50.242366 futex(0x22be844, FUTEX_WAIT_PRIVATE, 0, {tv_sec=299, tv_nsec=63999033} <unfinished ...>
175957 14:02:50.242403 futex(0x24778d0, FUTEX_WAKE_PRIVATE, 1) = 0
175957 14:02:50.242470 futex(0x22be844, FUTEX_WAKE_PRIVATE, 1) = 1
175956 14:02:50.242512 <... futex resumed> ) = 0
175956 14:02:50.242535 futex(0x22be7f0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
175957 14:02:50.242551 sched_yield( <unfinished ...>
175956 14:02:50.242566 <... futex resumed> ) = 0
175957 14:02:50.242590 <... sched_yield resumed> ) = 0
175956 14:02:50.242605 futex(0x22be840, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=99999716} <unfinished ...>
175957 14:02:50.242623 sched_yield()    = 0
175957 14:02:50.242667 sched_yield()    = 0
175957 14:02:50.242706 sched_yield()    = 0

[antiufo]

A simple strace -f -tt -o trace.txt pwsh -noprofile -c '$a = [IO.Directory]::GetFileSystemEntries("/usr/bin")' shows that even a simple .NET enumeration of that folder, without requesting any additional metadata (only IEnumerable<string>), causes each file to be stat'd. So I guess the bug belongs to corefx?

[0xd4d]

Sounds like this issue: https://github.com/PowerShell/PowerShell/issues/6577