Skip to content

With a transcript active, each native stderr line costs time proportional to the number of directories under PSModulePath #28133

Description

Summary

While Start-Transcript is active, every line a native command writes to stderr
(redirected with 2> or not) costs tens to hundreds of milliseconds of PowerShell
CPU time, compared with a few ms without a transcript. The cost grows with
the number of directories under the PSModulePath entries (at any depth; files
don't matter). Write-Host output under the same transcript is unaffected (~0.2 ms/line).
Possibly related: transcription may resolve Out-Default for each native stderr line.

Prerequisites

Steps to reproduce

Minimal (Linux):

Start-Transcript -Path ./t.log
Measure-Command { & bash -c 'for i in $(seq 1 200); do echo line $i >&2; done' 2> ./e.err }
Stop-Transcript

Cross-platform repro with a synthetic directory tree: Repro-TranscriptNativeStderr.ps1 (attached).
It measures native stderr lines with/without a transcript and with/without a tree of
empty directories added to PSModulePath.

# Repro: with a transcript active, each line a native command writes to stderr costs time
# that grows with the number of directories under the PSModulePath folders.
# Cross-platform: the native command is a child pwsh process writing to its stderr.
param (
	[int]$Lines = 100,          # stderr lines emitted per run
	# Shape of the extra PSModulePath entry: a broad, shallow tree of empty directories, similar to a
	# system folder like /usr/share. Defaults: 100 * (1 + 3 + 9 + 27 + 81) = 12,100 directories, 5 levels deep.
	[int]$Folders = 100,        # folders directly in the extra PSModulePath entry
	[int]$Branching = 3,        # subfolders per folder, at each level below
	[int]$Depth = 4             # levels of subfolders below each top-level folder
)

$Separator = [IO.Path]::PathSeparator
$Tree = Join-Path ([IO.Path]::GetTempPath()) "psmodulepath-repro-$PID"
# Only the leaves are created; CreateDirectory creates the intermediate levels.
$Leaves = [System.Collections.Generic.List[string]]::new()
foreach ($i in 1..$Folders) { $Leaves.Add((Join-Path $Tree "d$i")) }
foreach ($Level in 1..$Depth) {
	$Leaves = [System.Collections.Generic.List[string]]@(foreach ($Leaf in $Leaves) { foreach ($j in 1..$Branching) { Join-Path $Leaf "s$j" } })
}
foreach ($Leaf in $Leaves) { $null = [IO.Directory]::CreateDirectory($Leaf) }
$DirectoryCount = @(Get-ChildItem -LiteralPath $Tree -Directory -Recurse).Count

$ChildCommand = "1..$Lines | ForEach-Object { [Console]::Error.WriteLine(`"line `$_`") }"
$ErrFile = Join-Path ([IO.Path]::GetTempPath()) "repro-$PID.err"
$TranscriptFile = Join-Path ([IO.Path]::GetTempPath()) "repro-$PID.log"
$OriginalModulePath = $env:PSModulePath

function Measure-Run([bool]$WithTree, [bool]$WithTranscript) {
	$env:PSModulePath = $WithTree ? ($Tree + $Separator + $OriginalModulePath) : $OriginalModulePath
	if ($WithTranscript) { $null = Start-Transcript -Path $TranscriptFile -Force }
	$Elapsed = Measure-Command { & ([Environment]::ProcessPath) -NoProfile -Command $ChildCommand 2> $ErrFile }
	if ($WithTranscript) { $null = Stop-Transcript }
	$env:PSModulePath = $OriginalModulePath
	[pscustomobject]@{
		'Extra PSModulePath entry' = $WithTree ? "$DirectoryCount directories" : 'none'
		Transcript    = $WithTranscript
		'Total (ms)'  = [math]::Round($Elapsed.TotalMilliseconds)
		'Per line (ms)' = [math]::Round($Elapsed.TotalMilliseconds / $Lines, 1)
	}
}

try {
	"PowerShell $($PSVersionTable.PSVersion) on $([Runtime.InteropServices.RuntimeInformation]::OSDescription), $Lines stderr lines per run"
	@(
		Measure-Run $true  $false
		Measure-Run $true  $true
		Measure-Run $false $false
		Measure-Run $false $true
	) | Format-Table -AutoSize | Out-String -Width 200
	Write-Host "**************************************************************************************"
	$PSVersionTable
	Write-Host "**************************************************************************************"
}
finally {
	$env:PSModulePath = $OriginalModulePath
	Remove-Item -LiteralPath $Tree -Recurse -Force -ErrorAction Ignore
	Remove-Item -LiteralPath $ErrFile, $TranscriptFile -Force -ErrorAction Ignore
}

Expected behavior

Transcribing a native stderr line should cost about the same, independently of PSModulePath.

PowerShell 7.6.6 on Ubuntu 24.04.5 LTS, 100 stderr lines per run

Extra PSModulePath entry Transcript Total (ms) Per line (ms)
------------------------ ---------- ---------- -------------
12100 directories             False     390.00          3.90
12100 directories              True     similar         similar
none                          False     342.00          3.40
none                           True     similar         similar

Actual behavior

PowerShell 7.6.6 on Ubuntu 24.04.5 LTS, 100 stderr lines per run

Extra PSModulePath entry Transcript Total (ms) Per line (ms)
------------------------ ---------- ---------- -------------
12100 directories             False     390.00          3.90
12100 directories              True   31145.00        311.50
none                          False     342.00          3.40
none                           True    4514.00         45.10

Error details

N/A

Environment data

Name                           Value
----                           -----
PSVersion                      7.6.6
PSEdition                      Core
GitCommitId                    7.6.6
OS                             Ubuntu 24.04.5 LTS
Platform                       Unix
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0…}
PSRemotingProtocolVersion      2.4
SerializationVersion           1.1.0.1
WSManStackVersion              3.0

Visuals

Real-world impact

mysqldump --verbose writes ~530 stderr lines for a 132-table database. In a GitHub
Actions step where /usr/share is in PSModulePath (added by the azure/powershell
action), a transcript added ~6 minutes to a ~20-second export: 534 lines,
348 s wall time, 356 s of pwsh CPU time.

No response

Activity

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    Needs-TriageThe issue is new and needs to be triaged by a work group.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions