Prerequisites
Steps to reproduce
Preparation
Create test script (copytest.ps1)
[CmdletBinding()]
param (
[switch]$UseNewObject
)
$bufLen = 1MB
if ($UseNewObject) {
$buffer = New-Object -TypeName byte[] -ArgumentList $bufLen
}
else {
$buffer = [byte[]]::new($bufLen)
}
$srcFile = Join-Path -Path $PSScriptRoot -ChildPath 'srcFile'
$dstFile = Join-Path -Path $PSScriptRoot -ChildPath 'dstFile'
if (Test-Path -LiteralPath $dstFile) {
Remove-Item -LiteralPath $dstFile
}
try {
$inputStream = [System.IO.File]::Open($srcFile, [System.IO.FileMode]::Open, [System.IO.FileAccess]::Read, [System.IO.FileShare]::Read)
$outputStream = [System.IO.File]::Open($dstFile, [System.IO.FileMode]::Create, [System.IO.FileAccess]::Write, [System.IO.FileShare]::Read)
$stopwatch = [System.Diagnostics.Stopwatch]::new()
$stopwatch.Start()
while ($true) {
$ts = Measure-Command -Expression { $readCount = $inputStream.Read($buffer, 0, $buffer.Length) }
[PSCustomObject]@{
Operation = 'Read'
Count = $readCount
Time = $ts.TotalMilliseconds
}
if ($readCount -eq 0) {
break
}
$ts = Measure-Command -Expression { $outputStream.Write($buffer, 0, $readCount) }
[PSCustomObject]@{
Operation = 'Write'
Count = $readCount
Time = $ts.TotalMilliseconds
}
}
$stopwatch.Stop()
"----------"
"Time Total: $($stopwatch.Elapsed.TotalMilliseconds)"
}
finally {
$outputStream.Dispose()
$inputStream.Dispose()
}This script simply copies srcFile to dstFile using Stream read/write operation with byte[] buffer. With no parameter, buffer would be created using [byte[]]::new() method. With -UseNewObject parameter, buffer would be created using New-Object cmdlet.
create srcFile (10MB) in the same directory as copytest.ps1.
PS> fsutil file createnew srcFile (10MB)
Execution
PS> Enable-ExperimentalFeature PSAMSIMethodInvocationLogging
Restart pwsh
Case1 PSAMSIMethodInvocationLogging ON, new() method
PS> .\copytest.ps1
Operation Count Time
--------- ----- ----
Read 1048576 0.26
Write 1048576 10.06
Read 1048576 0.27
Write 1048576 3.84
Read 1048576 0.24
Write 1048576 3.71
Read 1048576 0.31
Write 1048576 3.87
Read 1048576 0.27
Write 1048576 4.15
Read 1048576 0.29
Write 1048576 3.79
Read 1048576 0.26
Write 1048576 3.78
Read 1048576 0.35
Write 1048576 3.98
Read 1048576 0.29
Write 1048576 3.92
Read 1048576 0.18
Write 1048576 3.51
Read 0 0.05
----------
Time Total: 51.1335
Case2 PSAMSIMethodInvocationLogging ON, New-Object cmdlet
PS> .\copytest.ps1 -UseNewObject
Operation Count Time
--------- ----- ----
Read 1048576 435.67
Write 1048576 531.13
Read 1048576 448.98
Write 1048576 458.24
Read 1048576 454.25
Write 1048576 448.41
Read 1048576 434.75
Write 1048576 474.36
Read 1048576 436.77
Write 1048576 461.22
Read 1048576 450.79
Write 1048576 465.32
Read 1048576 453.66
Write 1048576 466.68
Read 1048576 456.89
Write 1048576 459.88
Read 1048576 454.27
Write 1048576 446.89
Read 1048576 465.88
Write 1048576 457.08
Read 0 452.79
----------
Time Total: 9625.9351
PS> Disable-ExperimentalFeature PSAMSIMethodInvocationLogging
Restart pwsh
Case3 PSAMSIMethodInvocationLogging OFF, new() method
PS> .\copytest.ps1
Operation Count Time
--------- ----- ----
Read 1048576 0.48
Write 1048576 4.15
Read 1048576 0.35
Write 1048576 3.78
Read 1048576 0.27
Write 1048576 6.58
Read 1048576 0.28
Write 1048576 3.85
Read 1048576 0.38
Write 1048576 3.53
Read 1048576 0.26
Write 1048576 3.42
Read 1048576 0.25
Write 1048576 3.48
Read 1048576 0.24
Write 1048576 3.89
Read 1048576 0.32
Write 1048576 3.66
Read 1048576 0.19
Write 1048576 3.90
Read 0 0.09
----------
Time Total: 47.3111
Case4 PSAMSIMethodInvocationLogging OFF, New-Object cmdlet
PS> .\copytest.ps1 -UseNewObject
Operation Count Time
--------- ----- ----
Read 1048576 0.50
Write 1048576 4.22
Read 1048576 0.27
Write 1048576 3.96
Read 1048576 0.28
Write 1048576 3.94
Read 1048576 0.27
Write 1048576 4.52
Read 1048576 0.27
Write 1048576 4.02
Read 1048576 0.27
Write 1048576 3.66
Read 1048576 0.30
Write 1048576 3.65
Read 1048576 0.34
Write 1048576 3.93
Read 1048576 0.26
Write 1048576 3.80
Read 1048576 0.26
Write 1048576 3.60
Read 0 0.05
----------
Time Total: 46.4007
Strangely, only in Case2 (PSAMSIMethodInvocationLogging ON, and buffer created with New-Object cmdlet), Stream read/write operation become extreamly slow (more than 188 times).
PSAMSIMethodInvocationLogging will be stable in PS7.3 (#17962), so some scripts may slow down at that time.
Expected behavior
All 1-4 Cases take roughly the same time
Actual behavior
Stream read/write operation become extreamly slow in Case2
Error details
Environment data
Name Value
---- -----
PSVersion 7.3.0-preview.7
PSEdition Core
GitCommitId 7.3.0-preview.7
OS Microsoft Windows 10.0.19044
Platform Win32NT
PSCompatibleVersions {1.0, 2.0, 3.0, 4.0…}
PSRemotingProtocolVersion 2.3
SerializationVersion 1.1.0.1
WSManStackVersion 3.0Visuals
No response
Prerequisites
Steps to reproduce
Preparation
Create test script (copytest.ps1)
This script simply copies srcFile to dstFile using Stream read/write operation with byte[] buffer. With no parameter, buffer would be created using
[byte[]]::new()method. With-UseNewObjectparameter, buffer would be created usingNew-Objectcmdlet.create srcFile (10MB) in the same directory as copytest.ps1.
Execution
Restart pwsh
Case1 PSAMSIMethodInvocationLogging ON, new() method
Case2 PSAMSIMethodInvocationLogging ON, New-Object cmdlet
Restart pwsh
Case3 PSAMSIMethodInvocationLogging OFF, new() method
Case4 PSAMSIMethodInvocationLogging OFF, New-Object cmdlet
Strangely, only in Case2 (PSAMSIMethodInvocationLogging ON, and buffer created with New-Object cmdlet), Stream read/write operation become extreamly slow (more than 188 times).
PSAMSIMethodInvocationLogging will be stable in PS7.3 (#17962), so some scripts may slow down at that time.
Expected behavior
All 1-4 Cases take roughly the same timeActual behavior
Stream read/write operation become extreamly slow in Case2Error details
No errorEnvironment data
Visuals
No response