Hey, Scripting Guy! QuestionHey Scripting Guy! I have a script that I wrote, and I am interested in modifying it to try and make it run faster. I know I can use the Measure-Object Windows PowerShell cmdlet, but I want to run the script several times and get the average time it takes for each script to run. This task sounds like it might be a bit more complicated than I can handle because I am just beginning to learn Windows PowerShell. Could you possibly lend a hand?

-- JH

Hey, Scripting Guy! AnswerHello JH,

It is late at night on a Saturday night, and I am finishing up the Hey, Scripting Guy! articles for the week that Craig will be on vacation. You see, Craig and I decided to write ahead so there would not be a disruption while we take our vacations. The Scripting Wife and I leave tomorrow morning to go to New York City for a week of shows and museums. Craig goes on vacation the following week (he’ll be running with the vampires on the Olympic Peninsula). Because it is rather late, I am drinking a nice ginger tea. When I make ginger tea, I use a piece of fresh ginger root, a stalk of lemongrass, and a teaspoon of orange blossom honey. I put everything in my tea pot and let it steep for 15 minutes before drinking. It is very relaxing and goes well with Dave Brubeck. Because I am mellow, relaxed, and looking forward to a week of Broadway shows and museums, I am especially susceptible to suggestion. I will be glad to lend you a hand. The Test-TwoScripts.ps1 script, which I wrote for you, will allow you to test the performance of two scripts and will give you the results in a log file if you desire logged results. There is also a provision that will allow you to run your scripts multiple times to provide you with an average running time.

The complete Test-TwoScripts.ps1 script is seen here.

Test-TwoScripts.ps1

Param(
  [string]$baseLineScript,
  [string]$modifiedScript,
  [int]$numberOfTests = 20,
  [switch]$log
) #end param

Function Test-Scripts
{
  Param(
  [string]$baseLineScript,
  [string]$modifiedScript,
  [int]$numberOfTests,
  [switch]$log
) #end param
 Measure-Command -Expression { $baseLineScript }
 Measure-Command -Expression { $modifiedScript }
} #end Test-Scripts function

Function Get-Change($baseLine, $modified)
{
  (($baseLine - $modified)/$baseLine)*100
} #end Get-Change function

Function Get-TempFile
{
 [io.path]::GetTempFileName()
} #end Get-TempFile function

# *** Entry Point To Script
if($log) { $logFile = Get-TempFile }
For($i = 0 ; $i -le $numberOfTests ; $i++)
{
 "Test $i of $numberOfTests" ; start-sleep -m 50 ; cls
 $results= Test-Scripts -baseLineScript $baseLineScript -modifiedScript $modifedScript
 $baseLine += $results[0].TotalSeconds
 $modified += $results[1].TotalSeconds
 If($log)
  {
     "$baseLineScript run $i of $numberOfTests $(get-date)" >> $logFile
     $results[0] >> $logFile
     "$modifiedScript run $i of $numberOfTests $(get-date)" >> $logFile
     $results[1] >> $logFile
  } #if $log
} #for $i

"Average change over $numberOfTests tests"
"BaseLine: $baseLineScript average Total Seconds: $($baseLine/$numberOfTests)"
"Modified: $modifiedScript average Total Seconds: $($modified/$numberOfTests)"
"Percent Change: " + "{0:N2}" -f (Get-Change -baseLine $baseLine -modified $modified)
if($log)
{
 "Average change over $numberOfTests tests" >> $logFile
 "BaseLine: $baseLineScript average Total Seconds: $($baseLine/$numberOfTests)" >> $logFile
 "Modified: $modifiedScript average Total Seconds: $($modified/$numberOfTests)" >> $logFile
 "Percent Change: " + "{0:N2}" -f (Get-Change -baseLine $baseLine -modified $modified) >> $logFile
} #if $log
if($log) { Notepad $logFile }

The first thing we do in the Test-TwoScripts.ps1 script is create the command-line parameters. The first parameter, baseLineScript, is the path to the script that will be the baseline for comparison. Typically this is the script you used before you modified it. The second parameter is modifiedScript, and it is the script whose changes you wish to evaluate. Note that these two scripts do not need to be related to one another. The third parameter is the numberOfTests parameter. This number controls how many times the scripts will be run. This is because when testing, a script may run faster or slower on any given run. At times this may be due to files caching or other performance enhancements offered by the operating system, but at other times the difference may be due to resource contention or other anomalies. By running the scripts several times and averaging the results, a more accurate picture of the performance of the scripts can be gained. The last parameter is the switched log parameter. When the log parameter is present, it causes the script to write the performance information to a temporary text file that is displayed at the end of the completion of the script. The Param section of the script is seen here:

Param(

  [string]$baseLineScript,

  [string]$modifiedScript,

  [int]$numberOfTests = 20,

  [switch]$log

) #end param

The test-Scripts function is used to call the Measure-Command cmdlet for each of the two scripts to be tested. The Param section of the function receives two inputs: the baseLineScript parameter and the modifiedScript parameter. These were cut and pasted from the Param section to the script, because it was easier than typing everything a second time. Cutting and pasting the parameters also ensures that you avoid typing errors. This is shown here:

Function Test-Scripts

{

  Param(

  [string]$baseLineScript,

  [string]$modifiedScript

) #end param

After the parameters for the Test-Scripts function has been created, it is time to call the Measure-Command cmdlet. The Measure-Command cmdlet is called twice. The first time, the baseline script is passed to the expression parameter of the Measure-Command cmdlet. The string that is passed to the $baseLineScript parameter includes the full path to the script as well as all parameters the script requires to successfully execute. The second Measure-Command cmdlet is called to evaluate the performance of the modified script. The path to the modified script as well as the parameters required to set up the command is passed to the expression parameter of the Measure-Command cmdlet. This is seen here:

 Measure-Command -Expression { $baseLineScript }

 Measure-Command -Expression { $modifiedScript }

} #end Test-Scripts function

The Get-Change function is used to calculate the percentage increase or decrease in total running time between the baseline script and the modified script. The baseline parameter contains the total number of seconds the baseline script required to execute. The modified parameter contains the total number of seconds the modified script required to execute. It the Test-Scripts function was called several times (due to script performing multiple tests), the $baseLine variable and the $modified variable will contain the cumulative number of seconds running time from the entire series of tests. To calculate the percentage increase or decrease in total running time, the total number of seconds contained in the $modified variable is subtracted from the total number of seconds contained in the $baseLine variable. This number is then divided by the total number of seconds contained in the $baseLine variable. The result of this computation is then multiplied by 100. The Get-Change function is seen here:

Function Get-Change($baseLine, $modified)

{

  (($baseLine - $modified)/$baseLine)*100

} #end Get-Change function

After the Get-Change function is created, the Get-TempFile function is created. The Get-TempFile function calls the static GetTempFileName method from the Io.Path .NET Framework class. The Get-TempFile function is seen here:

Function Get-TempFile

{

 [io.path]::GetTempFileName()

} #end Get-TempFile function

After all the functions have been created, you arrive at the entry point to the script. The first thing to do is to see if the Test-TwoScripts.ps1 script was run with the –log switched parameter. If it was launched with the –log switched parameter, the $log variable will exist. And if the $log variable exists, the Get-TempFile function is called and the resulting temporary file name is stored in the $logFile variable. This is seen here:

if($log) { $logFile = Get-TempFile }

A for loop is used to count the number of tests to perform on the scripts. The number of tests is stored in the $numberOfTests variable. A status message is displayed in the Windows PowerShell console that indicates the test loop number. This section of the code is seen here:

For($i = 0 ; $i -le $numberOfTests ; $i++)

{

 "Test $i of $numberOfTests" ; start-sleep -m 50 ; cls

After the loop progress message is displayed, the Test-Scripts function is called. The Test-Scripts function returns two System.TimeSpan objects. These two objects are stored in the $results variable. This is seen here:

 $results= Test-Scripts -baseLineScript $baseLineScript -modifiedScript $modifedScript

Because the $results variable contains an array of two TimeSpan objects, you can index directly into the array and retrieve the value of the TotalSeconds variable. Use [0] to retrieve the first TimeSpan object and [1] to retrieve the second TimeSpan object. The total seconds from the current test run is added to the total seconds that are stored in the $baseLine and $modified variables. This is seen here:

 $baseLine += $results[0].TotalSeconds

 $modified += $results[1].TotalSeconds

If the script is run with the –log switched parameter, the name of the script, the test number, and the results are written to the log file. The code that does this is seen here:

 If($log)

  {

     "$baseLineScript run $i of $numberOfTests $(get-date)" >> $logFile

     $results[0] >> $logFile

     "$modifiedScript run $i of $numberOfTests $(get-date)" >> $logFile

     $results[1] >> $logFile

  } #if $log

} #for $i

After writing to the log file, it is time to display information to the Windows PowerShell console. The number of tests and the average time for each test run is displayed in the console for both the baseline and the modified scripts. The portion of the script that performs this action is shown here:

"Average change over $numberOfTests tests"

"BaseLine: $baseLineScript average Total Seconds: $($baseLine/$numberOfTests)"

"Modified: $modifiedScript average Total Seconds: $($modified/$numberOfTests)"

The percentage of change between the two scripts is calculated by using the Get-Change function. The {0:N2} format specifier indicates the percentage change to two decimal places. This is seen here:

"Percent Change: " + "{0:N2}" -f (Get-Change -baseLine $baseLine -modified $modified)

The same information that was just displayed to the console is written to the log file if the script is launched with the –log switched parameter. This section of the script is shown here:

if($log)

{

 "Average change over $numberOfTests tests" >> $logFile

 "BaseLine: $baseLineScript average Total Seconds: $($baseLine/$numberOfTests)" >> $logFile

 "Modified: $modifiedScript average Total Seconds: $($modified/$numberOfTests)" >> $logFile

 "Percent Change: " + "{0:N2}" -f (Get-Change -baseLine $baseLine -modified $modified) >> $logFile

} #if $log

After the log file has been updated, it is displayed by using Notepad. The code that displays the log file in Notepad is seen here:

if($log) { Notepad $logFile }

The log that is produced is seen here:

Image of log produced


Well, JH, we hope you found our helping hand useful. The performance testing of scripts after they have been modified is a good way to see if your changes are good ones. Join us tomorrow as we reach into the virtual mail bag for Quick-Hits Friday. Follow us on Twitter to stay up to date will all the latest news on the Script Center. You can also join our Facebook group for similar purposes. Don't forget about the Official Scripting Guys Forum where thousands of dedicated scripters from all over the world meet to discuss scripts. Drop us an e-mail at scripter@microsoft.com to let us know how things are going. Until tomorrow, have a great day!


Ed Wilson and Craig Liebendorfer, Scripting Guys