{"id":17931,"date":"2010-06-27T00:01:00","date_gmt":"2010-06-27T00:01:00","guid":{"rendered":"https:\/\/blogs.technet.microsoft.com\/heyscriptingguy\/2010\/06\/27\/hey-scripting-guy-weekend-scripter-timing-the-windows-powershell-pipeline\/"},"modified":"2010-06-27T00:01:00","modified_gmt":"2010-06-27T00:01:00","slug":"hey-scripting-guy-weekend-scripter-timing-the-windows-powershell-pipeline","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/scripting\/hey-scripting-guy-weekend-scripter-timing-the-windows-powershell-pipeline\/","title":{"rendered":"Hey, Scripting Guy! Weekend Scripter: Timing the Windows PowerShell Pipeline"},"content":{"rendered":"

 <\/p>\n

<\/p>\n

\n\n\"Bookmark<\/a><\/p>\n

<\/p>\n

 <\/p>\n

Microsoft Scripting Guy Ed Wilson here. I decided to get up early this morning and head out with my laptop, a camera, and my panama hat. My destination? Battery Park<\/a>. The Scripting Wife and I are in Charleston<\/a>, South Carolina<\/a>, for the weekend, and I thought it would be a great time to write some scripts. <\/p>\n

The Scripting Wife<\/a> has a tendency to hibernate on Saturday mornings<\/a>, and I learned a long time ago to be quiet. A hibernating bear is more safely awakened than a hibernating Scripting Wife. I therefore quietly escaped into the already hot and humid Charleston summer morning, and I went on a scouting mission to find a decent cup of tea. After checking out several different places—each of whom thought that a tea bag filled with what appeared to be crab grass<\/a> was a fine morning brew—I gave up and went to a little pastry shop that sold beignets<\/a> and a cup of coffee to go. As it turned out, the beignets were actually good, but the coffee tasted like burned cardboard. I am all for the waste hierarchy<\/a>; I just do not think it has any place in morning beverages. I finally made it to Battery Park and was accosted by the little furry guy you see just below. I think he wanted one of my beignets, but I was able to snap his picture and still safeguard my breakfast. <\/p>\n

\"Photo <\/a><\/p>\n

After getting rid of all the powdered sugar from my hands, I opened up my laptop and went to work. I had an idea for improving the performance of my ParseScriptCommands.ps1 script from yesterday<\/a>, and I wanted to test it out. <\/p>\n

I have often heard that Windows PowerShell<\/a> is inefficient when it comes to using the pipeline, and that it is actually quicker to store stuff in a variable and then iterate through the variable by using the Foreach<\/strong> statement. To be honest, I have not seen this behavior, but I have heard about it and have read about it on several blogs. It actually seems counterintuitive, but hey, who knows. <\/p>\n

When my ParseScriptCommands.ps1 script took several minutes to run (I have more than 1,300 scripts in my c:\\data\\psextras folder), I decided to put this claim to a test. The modified ModifiedParseScriptCommands.ps1 script is shown here.<\/p>\n

ModifiedParseScriptCommands.ps1<\/strong><\/p>\n

$errors<\/span> <\/span>=<\/span> <\/span>$null<\/span> 
<\/span>$logpath<\/span> <\/span>=<\/span> “C:\\a\\commandlog.txt” 
<\/span>$path<\/span> <\/span>=<\/span> “C:\\data\\PSExtras” 
<\/span>$scripts<\/span> <\/span>=<\/span> <\/span>Get-ChildItem<\/span> <\/span>-Path<\/span> <\/span>$path<\/span> <\/span>-Include<\/span> <\/span>*.ps1<\/span> <\/span>-Recurse<\/span> 
<\/span>ForEach<\/span>(<\/span>$s<\/span> <\/span>in<\/span> <\/span>$scripts<\/span>)<\/span> 
<\/span>{<\/span> 
<\/span>$script<\/span> <\/span>=<\/span> <\/span>$s<\/span>.fullname<\/span> 
<\/span>$scriptText<\/span> <\/span>=<\/span> <\/span>get-content<\/span> <\/span>-Path<\/span> <\/span>$script<\/span> 
<\/span>[system.management.automation.psparser]::Tokenize(<\/span>$scriptText<\/span>,<\/span> <\/span>[ref]<\/span>$errors<\/span>)<\/span> <\/span>|<\/span> 
<\/span>Foreach-object<\/span> <\/span>-Begin<\/span> <\/span>{<\/span> 
“Processing $script” <\/span>|<\/span> <\/span>Out-File<\/span> <\/span>-FilePath<\/span> <\/span>$logPath<\/span> <\/span>-Append<\/span> <\/span>}<\/span> <\/span>`<\/span> 
<\/span>-process<\/span> <\/span>{<\/span> <\/span>if<\/span>(<\/span>$_<\/span>.<\/span>type<\/span> <\/span>-eq<\/span> “command”<\/span>)<\/span> 
<\/span>{<\/span> “`t $($_.content)” <\/span>|<\/span> <\/span>Out-File<\/span> <\/span>-FilePath<\/span> <\/span>$logpath<\/span> <\/span>-Append<\/span> <\/span>}<\/span> <\/span>}<\/span> 
<\/span>}<\/span> 
<\/span>#<\/span>notepad<\/span> <\/span>$logpath<\/span> <\/p>\n

Only two lines were changed in the script. The first one stores the results of the Get-ChildItem cmdlet<\/a> in the $Scripts<\/strong> variable, which is shown here:<\/p>\n

$scripts<\/span> <\/span>=<\/span> <\/span>Get-ChildItem<\/span> <\/span>-Path<\/span> <\/span>$path<\/span> <\/span>-Include<\/span> <\/span>*.ps1<\/span> <\/span>-Recurse<\/span> <\/p>\n

The second change moves from the ForEach-Object cmdlet<\/a> to the ForEach<\/strong> statement. This change is shown here: <\/p>\n

ForEach<\/span>(<\/span>$s<\/span> <\/span>in<\/span> <\/span>$scripts<\/span>)<\/span> <\/p>\n

I commented out the line in each script that opens the log in Notepad, and I used my Test-TwoScripts.ps1 script to evaluate the changes. The Test-TwoScripts.ps1 script is shown here.<\/p>\n

Test-TwoScripts.ps1<\/strong><\/p>\n

Param(<\/span> 
<\/span>[string]<\/span>$baseLineScript<\/span>,<\/span> 
<\/span>[string]<\/span>$modifiedScript<\/span>,<\/span> 
<\/span>[int]<\/span>$numberOfTests<\/span> <\/span>=<\/span> <\/span>1<\/span>,<\/span> 
<\/span>[switch]<\/span>$log<\/span> 
<\/span>)<\/span> <\/span>#<\/span>end<\/span> <\/span>param<\/span> 
<\/span>Function<\/span> <\/span>Test-Scripts<\/span> 
<\/span>{<\/span> 
<\/span>Param(<\/span> 
<\/span>[string]<\/span>$baseLineScript<\/span>,<\/span> 
<\/span>[string]<\/span>$modifiedScript<\/span> 
<\/span>)<\/span> <\/span>#<\/span>end<\/span> <\/span>param<\/span> 
<\/span>Measure-Command<\/span> <\/span>-Expression<\/span> <\/span>{<\/span> <\/span>Invoke-Expression<\/span> <\/span>-command<\/span> <\/span>$baseLineScript<\/span> <\/span>}<\/span> 
<\/span>Measure-Command<\/span> <\/span>-Expression<\/span> <\/span>{<\/span> <\/span>Invoke-Expression<\/span> <\/span>-command<\/span> <\/span>$modifiedScript<\/span> <\/span>}<\/span> 
<\/span>}<\/span> <\/span>#<\/span>end<\/span> <\/span>Test-Scripts<\/span> <\/span>function<\/span> 
<\/span>Function<\/span> <\/span>Get-Change(<\/span>$baseLine<\/span>,<\/span> <\/span>$modified<\/span>)<\/span> 
<\/span>{<\/span> 
<\/span>((<\/span>$baseLine<\/span> <\/span>–<\/span> <\/span>$modified<\/span>)\/<\/span>$baseLine<\/span>)*<\/span>100<\/span> 
<\/span>}<\/span> <\/span>#<\/span>end<\/span> <\/span>Get-Change<\/span> <\/span>function<\/span> 
<\/span>Function<\/span> <\/span>Get-TempFile<\/span> 
<\/span>{<\/span> 
<\/span>[io.path]::GetTempFileName()<\/span> 
<\/span>}<\/span> <\/span>#<\/span>end<\/span> <\/span>Get-TempFile<\/span> <\/span>function<\/span> 
<\/span>#<\/span> <\/span>***<\/span> <\/span>Entry<\/span> <\/span>Point<\/span> <\/span>To<\/span> <\/span>Script<\/span> 
<\/span>if<\/span>(<\/span>$log<\/span>)<\/span> <\/span>{<\/span> <\/span>$logFile<\/span> <\/span>=<\/span> <\/span>Get-TempFile<\/span> <\/span>}<\/span> 
<\/span>$results<\/span> <\/span>=<\/span> <\/span>$modified<\/span> <\/span>=<\/span> <\/span>$baseLine<\/span> <\/span>=<\/span> <\/span>$null<\/span> 
<\/span>For(<\/span>$i<\/span> <\/span>=<\/span> <\/span>0<\/span> <\/span>;<\/span> <\/span>$i<\/span>&nbsp\n;<\/span>-le<\/span> <\/span>$numberOfTests<\/span> <\/span>;<\/span> <\/span>$i++<\/span>)<\/span> 
<\/span>{<\/span> 
“Test $i of $numberOfTests” <\/span>;<\/span> <\/span>start-sleep<\/span> <\/span>-m<\/span> <\/span>50<\/span> 
<\/span>$results<\/span>=<\/span> <\/span>Test-Scripts<\/span> <\/span>-baseLineScript<\/span> <\/span>$baseLineScript<\/span> <\/span>-modifiedScript<\/span> <\/span>$modifiedScript<\/span> 
<\/span>$baseLine<\/span> <\/span>+<\/span>=<\/span> <\/span>$results<\/span>[<\/span>0<\/span>].TotalSeconds<\/span> 
<\/span>$modified<\/span> <\/span>+<\/span>=<\/span> <\/span>$results<\/span>[<\/span>1<\/span>].TotalSeconds<\/span> 
<\/span>If<\/span>(<\/span>$log<\/span>)<\/span> 
<\/span>{<\/span> 
“$baseLineScript run $i of $numberOfTests $(get-date)” <\/span>>><\/span> <\/span>$logFile<\/span> 
<\/span>$results<\/span>[<\/span>0<\/span>]<\/span> <\/span>>><\/span> <\/span>$logFile<\/span> 
“$modifiedScript run $i of $numberOfTests $(get-date)” <\/span>>><\/span> <\/span>$logFile<\/span> 
<\/span>$results<\/span>[<\/span>1<\/span>]<\/span> <\/span>>><\/span> <\/span>$logFile<\/span> 
<\/span>}<\/span> <\/span>#if<\/span> <\/span>$log<\/span> 
<\/span>}<\/span> <\/span>#<\/span>for<\/span> <\/span>$i<\/span> 
“Average change over $numberOfTests tests” 
“BaseLine: $baseLineScript average Total Seconds: $($baseLine\/$numberOfTests)” 
“Modified: $modifiedScript average Total Seconds: $($modified\/$numberOfTests)” 
“Percent Change: ” <\/span>+<\/span> “{0:N2}” <\/span>-f<\/span> <\/span>(Get-Change<\/span> <\/span>-baseLine<\/span> <\/span>$baseLine<\/span> <\/span>-modified<\/span> <\/span>$modified<\/span>)<\/span> 
<\/span>if<\/span>(<\/span>$log<\/span>)<\/span> 
<\/span>{<\/span> 
“Average change over $numberOfTests tests” <\/span>>><\/span> <\/span>$logFile<\/span> 
“BaseLine: $baseLineScript average Total Seconds: $($baseLine\/$numberOfTests)” <\/span>>><\/span> <\/span>$logFile<\/span> 
“Modified: $modifiedScript average Total Seconds: $($modified\/$numberOfTests)” <\/span>>><\/span> <\/span>$logFile<\/span> 
“Percent Change: ” <\/span>+<\/span> “{0:N2}” <\/span>-f<\/span> <\/span>(Get-Change<\/span> <\/span>-baseLine<\/span> <\/span>$baseLine<\/span> <\/span>-modified<\/span> <\/span>$modified<\/span>)<\/span> <\/span>>><\/span> <\/span>$logFile<\/span> 
<\/span>}<\/span> <\/span>#if<\/span> <\/span>$log<\/span> 
<\/span>if<\/span>(<\/span>$log<\/span>)<\/span> <\/span>{<\/span> <\/span>Notepad<\/span> <\/span>$logFile<\/span> <\/span>}<\/span> <\/p>\n

The results of the change are seen in the following image. The modified script actually took nine seconds longer to run. Therefore, storing the results in a variable rather than using the pipeline caused a 7 percent performance hit. <\/p>\n

\"Image <\/a><\/p>\n

Many of the things written about the pipeline are probably referring to Windows PowerShell 1.0, and because of the performance tuning that took place for Windows PowerShell 2.0, they are no longer applicable. However, your environment and your needs may be different. This is where testing comes into play. <\/p>\n

If you want to know exactly what we will be looking at tomorrow, follow us on Twitter<\/a> or Facebook<\/a>. If you have any questions, send email to us at scripter@microsoft.com<\/a>, or post your questions on the Official Scripting Guys Forum<\/a>. See you tomorrow. Until then, peace.<\/p>\n

Ed Wilson and Craig Liebendorfer, Scripting Guys<\/strong><\/p>\n","protected":false},"excerpt":{"rendered":"

    Microsoft Scripting Guy Ed Wilson here. I decided to get up early this morning and head out with my laptop, a camera, and my panama hat. My destination? Battery Park. The Scripting Wife and I are in Charleston, South Carolina, for the weekend, and I thought it would be a great time to […]<\/p>\n","protected":false},"author":595,"featured_media":87096,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[2,3,4,61,45],"class_list":["post-17931","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-scripting","tag-running","tag-scripting-guy","tag-scripting-techniques","tag-weekend-scripter","tag-windows-powershell"],"acf":[],"blog_post_summary":"

    Microsoft Scripting Guy Ed Wilson here. I decided to get up early this morning and head out with my laptop, a camera, and my panama hat. My destination? Battery Park. The Scripting Wife and I are in Charleston, South Carolina, for the weekend, and I thought it would be a great time to […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/17931","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/users\/595"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/comments?post=17931"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/posts\/17931\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/media\/87096"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/media?parent=17931"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/categories?post=17931"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/scripting\/wp-json\/wp\/v2\/tags?post=17931"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}