Observations on writing to Screen and File in PowerShell

When writing a PowerShell script, you are typically doing “something” with “something” and getting a result based on this “doing”.

This is all well and good, but after you have gotten your result what do you do with the data? Two common scenarios are writing the result either to the screen or to a file. If the script is doing a lot of calculations, it’s quite common to also give the user some kind of feedback while it’s working, to indicate that it’s actually doing what it’s suppose to do and that it haven’t stalled.

I have written a few blog post before about using a progress bar to give users visual feedback during long-running scripts. But after one of these posts, Brenton Blawat made me aware that using Write-Progress has it’s price on overall script execution time. I was aware that writing anything to the screen is associated with some kind of overhead, but I decided to do some tests to see exactly how much overhead are generated doing different kinds of interaction to either the screen or when writing results to a file.

I wrote a script performing the following tests:

  • Test 1 (m1) – The baseline. This test is just performing an easy calculation, but is otherwise not doing anything with the results.
  • Test 2 (m2) – This test is using Write-Host to write the result of the calculations to the screen.
  • Test 3 (m3) – This test is using Write-Output to write the output of the calculations.
  • Test 4 (m4) – This test is saving the results of the calculations to an Array.
  • Test 5 (m5) – This test is saving the results of the calculations to an ArrayList.
  • Test 6 (m6) – This test is using Write-Progress to create a progress bar while doing the calculations.
  • Test 7 (m7) – This test is writing the result of the calculations to a file, doing file writes after each calculation.
  • Test 8 (m8) – This test is writing the results of the calculations to a file, but only writing the file after all the calculations are done. In the meantime the results are saved in an ArrayList.

I ran the script, using Measure-Command to take the measurement data, a total of 10 times; 5 times in PowerShell ISE and 5 times from the PowerShell console.

I then calculated the average value of each of the 5 runs per test, so that I could see if it made any difference whether the script was run in ISE or the console.

This is a chart of the result of my testing:

resultChart

And here a a table of the average data that I collected. All values are in milliseconds.

m1 m2 m3 m4 m5 m6 m7 m8
ISE 2 4683 538 2675 130 4411 8179 619
Console 1 3351 516 2264 118 38982 7760 581

What surprised me the most was that, although running the script in the console was marginally faster in almost all cases, the Write-Progress cmdlet was significantly slower in the console compared to running it in the ISE.

Other than that I think most of the results were as expected.

I think the lessons learned can be summed up thus:

  • Use Write-Output instead of Write-Host
  • Use ArrayList instead of Array
  • Use as few disk writes as possible
  • Only use Write-Progress if you absolutely must

This is the test script I used in case you want to test for yourself:


$iterations = 10000
$saveFile = 'C:\Users\grave\Scripts\OverheadTests\results.txt'
$m1Description = 'Refence: Only doing calculations'
Write-Host 'Starting Measurement 1'
$m1 = Measure-Command {
1..100 | ForEach-Object {
$_ + ($_ * $_)
}
}
$m2Description = 'Using Write-Host to output result of calculation to the host'
Write-Host 'Starting Measurement 2'
$m2 = Measure-Command {
1..$iterations | ForEach-Object {
Write-Host "Result of calculation: $($_ + ($_ * $_))"
}
}
$m3Description = 'Using Write-Output to output result of calculation'
Write-Host 'Starting Measurement 3'
$m3 = Measure-Command {
1..$iterations | ForEach-Object {
Write-Output "Result of calculation: $($_ + ($_ * $_))"
}
}
$m4Description = 'Saving result of calculation to an Array'
Write-Host 'Starting Measurement 4'
$m4 = Measure-Command {
$result = @()
1..$iterations | ForEach-Object {
$result += $_ + ($_ * $_)
}
}
$m5Description = 'Saving result of calculation to an ArrayList'
Write-Host 'Starting Measurement 5'
$m5 = Measure-Command {
$resultAL = New-Object System.Collections.ArrayList
1..$iterations | ForEach-Object {
[void]$resultAL.Add(($_ + ($_ * $_)))
}
}
$m6Description = 'Using Write-Progress to output result of calculation'
Write-Host 'Starting Measurement 6'
$count = 0
$m6 = Measure-Command {
1..$iterations | ForEach-Object {
$count++
Write-Progress -Activity 'Processing' -CurrentOperation "Result: $($_ + ($_ * $_))" -PercentComplete (($count / $iterations * 100))
}
}
$m7Description = 'Save result of calculation to file, write per iteration'
Write-Host 'Starting Measurement 7'
$m7 = Measure-Command {
1..$iterations | ForEach-Object {
$result = $_ + ($_ * $_)
$result | Out-File -FilePath $saveFile -Append
}
}
Remove-Item -Path $saveFile -Force
$m8Description = 'Save result of calculation to file, write when done (using ArrayList to store results)'
Write-Host 'Starting Measurement 8'
$m8 = Measure-Command {
$resultAL = New-Object System.Collections.ArrayList
1..$iterations | ForEach-Object {
[void]$resultAL.Add(($_ + ($_ * $_)))
}
$resultAL | Out-File -FilePath $saveFile -Append
}
Remove-Item -Path $saveFile -Force
Write-Host 'Finished all measurements'
Write-Host ''
Write-Output ([PSCustomObject] [Ordered] @{
Milliseconds = [math]::Round($m1.TotalMilliseconds)
Description = $m1Description
})
Write-Output ([PSCustomObject] [Ordered] @{
Milliseconds = [math]::Round($m2.TotalMilliseconds)
Description = $m2Description
})
Write-Output ([PSCustomObject] [Ordered] @{
Milliseconds = [math]::Round($m3.TotalMilliseconds)
Description = $m3Description
})
Write-Output ([PSCustomObject] [Ordered] @{
Milliseconds = [math]::Round($m4.TotalMilliseconds)
Description = $m4Description
})
Write-Output ([PSCustomObject] [Ordered] @{
Milliseconds = [math]::Round($m5.TotalMilliseconds)
Description = $m5Description
})
Write-Output ([PSCustomObject] [Ordered] @{
Milliseconds = [math]::Round($m6.TotalMilliseconds)
Description = $m6Description
})
Write-Output ([PSCustomObject] [Ordered] @{
Milliseconds = [math]::Round($m7.TotalMilliseconds)
Description = $m7Description
})
Write-Output ([PSCustomObject] [Ordered] @{
Milliseconds = [math]::Round($m8.TotalMilliseconds)
Description = $m8Description
})

2 comments

  1. If you use a stopwatch the results for m6 will be a lot different (at least a factor of 10), see the gist I created below with a little modified code.


    $iterations = 10000
    $saveFile = 'C:\Users\heman\Desktop\OverheadTests\results.txt'
    $m1Description = 'Refence: Only doing calculations'
    Write-Host 'Starting Measurement 1'
    $m1 = Measure-Command {
    1..100 | ForEach-Object {
    $_ + ($_ * $_)
    }
    }
    $m2Description = 'Using Write-Host to output result of calculation to the host'
    Write-Host 'Starting Measurement 2'
    $m2 = Measure-Command {
    1..$iterations | ForEach-Object {
    Write-Host "Result of calculation: $($_ + ($_ * $_))"
    }
    }
    $m3Description = 'Using Write-Output to output result of calculation'
    Write-Host 'Starting Measurement 3'
    $m3 = Measure-Command {
    1..$iterations | ForEach-Object {
    Write-Output "Result of calculation: $($_ + ($_ * $_))"
    }
    }
    $m4Description = 'Saving result of calculation to an Array'
    Write-Host 'Starting Measurement 4'
    $m4 = Measure-Command {
    $result = @()
    1..$iterations | ForEach-Object {
    $result += $_ + ($_ * $_)
    }
    }
    $m5Description = 'Saving result of calculation to an ArrayList'
    Write-Host 'Starting Measurement 5'
    $m5 = Measure-Command {
    $resultAL = New-Object System.Collections.ArrayList
    1..$iterations | ForEach-Object {
    [void]$resultAL.Add(($_ + ($_ * $_)))
    }
    }
    $m6Description = 'Using Write-Progress to output result of calculation'
    Write-Host 'Starting Measurement 6'
    $count = 0
    $m6 = Measure-Command {
    $sw = [System.Diagnostics.Stopwatch]::StartNew()
    1..$iterations | ForEach-Object {
    $count++
    if ($sw.Elapsed.TotalMilliseconds -ge 500){
    Write-Progress -Activity 'Processing' -CurrentOperation "Result: $($_ + ($_ * $_))" -PercentComplete (($count / $iterations * 100))
    $sw.Reset();
    $sw.Start();
    }
    }
    }
    $m7Description = 'Save result of calculation to file, write per iteration'
    Write-Host 'Starting Measurement 7'
    $m7 = Measure-Command {
    1..$iterations | ForEach-Object {
    $result = $_ + ($_ * $_)
    $result | Out-File -FilePath $saveFile -Append
    }
    }
    Remove-Item -Path $saveFile -Force
    $m8Description = 'Save result of calculation to file, write when done (using ArrayList to store results)'
    Write-Host 'Starting Measurement 8'
    $m8 = Measure-Command {
    $resultAL = New-Object System.Collections.ArrayList
    1..$iterations | ForEach-Object {
    [void]$resultAL.Add(($_ + ($_ * $_)))
    }
    $resultAL | Out-File -FilePath $saveFile -Append
    }
    Remove-Item -Path $saveFile -Force
    Write-Host 'Finished all measurements'
    Write-Host ''
    Write-Output ([PSCustomObject] [Ordered] @{
    Milliseconds = [math]::Round($m1.TotalMilliseconds)
    Description = $m1Description
    })
    Write-Output ([PSCustomObject] [Ordered] @{
    Milliseconds = [math]::Round($m2.TotalMilliseconds)
    Description = $m2Description
    })
    Write-Output ([PSCustomObject] [Ordered] @{
    Milliseconds = [math]::Round($m3.TotalMilliseconds)
    Description = $m3Description
    })
    Write-Output ([PSCustomObject] [Ordered] @{
    Milliseconds = [math]::Round($m4.TotalMilliseconds)
    Description = $m4Description
    })
    Write-Output ([PSCustomObject] [Ordered] @{
    Milliseconds = [math]::Round($m5.TotalMilliseconds)
    Description = $m5Description
    })
    Write-Output ([PSCustomObject] [Ordered] @{
    Milliseconds = [math]::Round($m6.TotalMilliseconds)
    Description = $m6Description
    })
    Write-Output ([PSCustomObject] [Ordered] @{
    Milliseconds = [math]::Round($m7.TotalMilliseconds)
    Description = $m7Description
    })
    Write-Output ([PSCustomObject] [Ordered] @{
    Milliseconds = [math]::Round($m8.TotalMilliseconds)
    Description = $m8Description
    })

    This was a learning that I came across a few months ago when working on some issues with write-progress slowing down some file operations and saw the following SO answer:
    http://stackoverflow.com/questions/21304282/how-to-improve-the-performance-of-write-progress

    Like

    1. Thanks for the feedback! That is actually a very good “solution” to the problem of overhead when using Write-Progress! Thanks!

      Like

Leave a comment