Write-Host 150ms+ delay after first command when executed from profile #7577
Description
Write-Host has a 150ms delay (~50ms on Linux) when called from a profile, but it doesn't if called directly. I thought maybe this would be due to CPU startup time but it's not, it's consistent every time, rarely wavers.
This is important because custom prompts and whatnot use write-host, and so a delay for no reason makes powershell feel more "sluggish" on startup.
Steps to reproduce
Save the following to ~\desktop\cpscript.ps1. Run ~\desktop\cpscript.ps1 from commandline. Normal expected behavior.
Add ~\desktop\cpscript.ps1 to profile.ps1. Start powershell normally. Second write-host takes +150ms to run, the remainder run normally.
$cpnum = 0
$stopwatch = [system.diagnostics.stopwatch]::StartNew()
"Checkpoint $($cpnum++;$cpnum): $($stopwatch.elapsed.milliseconds)ms"
"Checkpoint $($cpnum++;$cpnum): $($stopwatch.elapsed.milliseconds)ms"
"Checkpoint $($cpnum++;$cpnum): $($stopwatch.elapsed.milliseconds)ms"
"Checkpoint $($cpnum++;$cpnum): $($stopwatch.elapsed.milliseconds)ms"
"Checkpoint $($cpnum++;$cpnum): $($stopwatch.elapsed.milliseconds)ms"
write-host "WHCheckpoint $($cpnum++;$cpnum): $($stopwatch.elapsed.milliseconds)ms"
write-host "WHCheckpoint $($cpnum++;$cpnum): $($stopwatch.elapsed.milliseconds)ms"
write-host "WHCheckpoint $($cpnum++;$cpnum): $($stopwatch.elapsed.milliseconds)ms"
write-host "WHCheckpoint $($cpnum++;$cpnum): $($stopwatch.elapsed.milliseconds)ms"
write-host "WHCheckpoint $($cpnum++;$cpnum): $($stopwatch.elapsed.milliseconds)ms"Doesn't have to be write host, can also be write-output, write-warning, etc. and it has the same effect.
Expected behavior
What happens when you run ~\desktop\CPScript.ps1 in a normal session
Checkpoint 1: 0ms
Checkpoint 2: 0ms
Checkpoint 3: 1ms
Checkpoint 4: 1ms
Checkpoint 5: 1ms
WHCheckpoint 6: 2ms
WHCheckpoint 7: 3ms
WHCheckpoint 8: 3ms
WHCheckpoint 9: 4ms
WHCheckpoint 10: 5ms
Actual behavior
What happens when you run it called from the profile
Checkpoint 1: 5ms
Checkpoint 2: 10ms
Checkpoint 3: 10ms
Checkpoint 4: 11ms
Checkpoint 5: 11ms
WHCheckpoint 6: 11ms
WHCheckpoint 7: 178ms
WHCheckpoint 8: 179ms
WHCheckpoint 9: 179ms
WHCheckpoint 10: 180ms
Linux
Checkpoint 1: 5ms
Checkpoint 2: 12ms
Checkpoint 3: 12ms
Checkpoint 4: 12ms
Checkpoint 5: 12ms
WHCheckpoint 6: 12ms
WHCheckpoint 7: 75ms
WHCheckpoint 8: 75ms
WHCheckpoint 9: 76ms
WHCheckpoint 10: 76ms
Same behavior less pronounced.
Appears to happen on PS5.1 as well
Checkpoint 1: 4ms
Checkpoint 2: 8ms
Checkpoint 3: 8ms
Checkpoint 4: 9ms
Checkpoint 5: 9ms
WHCheckpoint 6: 10ms
WHCheckpoint 7: 180ms
WHCheckpoint 8: 181ms
WHCheckpoint 9: 186ms
WHCheckpoint 10: 187ms
Note that the first write-host works just fine, so whatever is introducting the delay is code after write-host writes to console.
Environment data
Name Value
---- -----
PSVersion 6.1.0-preview.4
PSEdition Core
GitCommitId 6.1.0-preview.4
OS Microsoft Windows 10.0.17134
Platform Win32NT
PSCompatibleVersions {1.0, 2.0, 3.0, 4.0...}
PSRemotingProtocolVersion 2.3
SerializationVersion 1.1.0.1
WSManStackVersion 3.0
Happens in PS5.1 as well.