Evolution of a Script: Timing Operations

Posted on by

I just love PowerShell!  One of the things I love the most about it is that you can pick the level of programming you want, write a script and then evolve it to meet whatever need you have.  Sometimes you want something quick and dirty and other times you want something you’ll share with others and then other times you want something that is going to be used in production.

When I was earning my living on Unix systems, I used to write quick and dirty CSH scripts (yeah – I was one of those guys) but then when I wanted something more formal or to share with others, often I would throw away the script and restart from scratch.  I don’t do that with PowerShell.

This morning I was reviewing someone’s scripts that they were going to use to perform a large scale upgrade to a datacenter.  The code had lots of validation and verbose output and then they had lots of code that looked like this:

  1. #Start Stopwatch  
  2. $sw = [Diagnostics.Stopwatch]::StartNew()  
  3. #…..  
  4. $sw.Stop()  
  5.           
  6. Write-Verbose “Total ElapsedTime: $($sw.Elapsed.TotalSeconds) Seconds”  

I thought that I would help out by providing a helper function so I wrote my first version of the script like this:

  1. Function Measure-Time  
  2. {  
  3. param(  
  4. #ScriptBlock that you want to measure the timing of  
  5. [Parameter(Position=0, Mandatory=1)]  
  6. [ScriptBlock]$ScriptBlock  
  7. )  
  8.     $StopWatch = [Diagnostics.Stopwatch]::StartNew()  
  9.     &$ScriptBlock  
  10.     $StopWatch.Stop()  
  11.           
  12.       
  13.     Write-Verbose “Total ElapsedTime: $($StopWatch.Elapsed.TotalSeconds) Seconds”  
  14. }  
  15.   
  16. Set-Alias Time Measure-Time  
  17.   
  18. #Example usage:  
  19. Time {gps *ss} -Verbose  

So that worked great but then I thought about some problems:

  • Using the variables $Stopwatch and $ScriptBlock, it meant that those variables couldn’t be used in the scriptblock that was passed in.  Whenever you have a situation like this, the convention is to put 2 “_” in front of a name so I renamed them $__ScriptBlock and $__StopWatch.
  • I didn’t have any help.  I can never remember the keywords to add comment-based help so what I do is to start a new script, type CTRL-J to bring up snippets, select the CMDLET snippet and then cut/paste the help from it and use it to fill it in.
  • I wanted the user to be able to specify their own message so I provided a -__FormatString variable.
  • If you are upgrading a datacenter, you want to use the belt and suspenders approach so I thought this information should be logged to the eventlog (this started the next leg of the journey but more about that later).

The resultant script was starting to look like something worth sharing:

  1. <#  
  2. .Synopsis  
  3.    Measure how long something takes  
  4. .DESCRIPTION  
  5.    This script measures how long it takes to run a sequence of code (a ScriptBlock).  
  6.    The message is sent to the Verbose channel so to see it, you either need to have  
  7.    $VerbosePreference set to “Continue” or specify -Verbose.  
  8. .EXAMPLE  
  9.    Measure-Time { get-process } -Verbose  
  10. .EXAMPLE  
  11.    time {get-process} DataCenterUpgrade “It took {0:N3} seconds to run this” -verbose  
  12. #>  
  13. Function Measure-Time  
  14. {  
  15. param(  
  16. #ScriptBlock that you want to measure the timing of  
  17. [Parameter(Position=0, Mandatory=1)]  
  18. [ScriptBlock]$__ScriptBlock,  
  19.   
  20. # Name of the LogSource in the APPLICATION EventLog   
  21. # that these events will show up in.  
  22. #   
  23. # If you don’t provide a value – no log entry will be made.  
  24. [Parameter(Position=1)]  
  25. [String]$__LogSource = $null,  
  26.   
  27. # An alternate format string for the Message  
  28. [Parameter(Position=2)]  
  29. [String]$__FormatString=“Total ElapsedTime: {0:N1} Seconds”  
  30.   
  31. )  
  32.     $_StopWatch = [Diagnostics.Stopwatch]::StartNew()  
  33.     &$__ScriptBlock  
  34.     $_StopWatch.Stop()  
  35.           
  36.     $Message = $__FormatString -f $_StopWatch.Elapsed.TotalSeconds  
  37.     Write-Verbose $Message          
  38.     if ($__LogSource)  
  39.     {  
  40.             Write-EventLog -LogName Application `  
  41.             -Source $__LogSource `  
  42.             -EntryType Information `  
  43.             -EventId 1 -Message $Message   
  44.     }  
  45. }  
  46. Set-Alias -Name Time -Value Measure-Time  
  47.   
  48. #Example usage:  
  49. Time {gps *ss} DataCenterUpgrade -Verbose  

So everything looked great until I went to run it and then it barfed complaining that there was no DataSource called “DataCenterUpgrade”.  I’ve always believed that the different between a quick and dirty script and a production script was the error handling.  When you are in a datacenter at 3am when you expected to be home at 7pm the previous evening and everything it turning to crap – you want to have GREAT error messages.

I started off by adding some code to check for the DataSource and create it if it didn’t exist:

  1. if ($__LogSource)  
  2. {  
  3.   if (![System.Diagnostics.EventLog]::SourceExists($__LogSource))  
  4.  {  
  5.     [System.Diagnostics.EventLog]::CreateEventSource($__LogSource, “Application”)  
  6.   }  
  7. }  

The problem with that is that it only works if you are running with Admin privs (which I wasn’t of course).  So I put in a TRY/Catch and spent some time crafting an excellent error message:

  1. if ($__LogSource)  
  2. {  
  3.   try {  
  4.     if (![System.Diagnostics.EventLog]::SourceExists($__LogSource))  
  5.     {  
  6.       [System.Diagnostics.EventLog]::CreateEventSource($__LogSource, “Application”)  
  7.     }  
  8.   
  9.     Write-EventLog -LogName Application -Source $__LogSource `  
  10.       -EntryType Information -EventId 1 -Message $Message  
  11.   }  
  12.   catch [Exception] # An exception means you don’t have the privs to create the source  
  13.   {  
  14.     Write-Error -Message “Cannot Write to or Create EventLogSource ($__LogSource)” `  
  15.       -Exception $_.Exception `  
  16.       -Category ResourceUnavailable `  
  17.       -TargetObject $__LogSource `  
  18.       -RecommendedAction “Create LogSource ($__LogSource) using an account with Admin privs” `  
  19.       -ErrorId “CantWriteLog,Measure-Time” `  
  20.       -CategoryReason CantFindorCreateLogSource   
  21.   }  
  22. }  

This produced a great error message so I was feeling pretty good about my script.  Next I decided to look at the EventLog and realized that it was now logging perfectly accurate and perfectly useless information.  It was saying how long it took to do something but not how long it took to do WHAT?  Now I could have handled this using the FormatString:

  1. Time {gps *ss} DataCenterUpgrade “It took {0:N} to Gps”  
  2. Time {Step2  } DataCenterUpgrade “It took {0:N} to do STEP2”  

But that looks like a horrible user experience so I decided to include the scriptblock in the eventlog.  It then hit me that I had no idea how long the scriptblock would be but that it I was sure that the eventlog had a limit on the maximum size of the entry.  I could have researched this but I decided to experiment instead.  I created a DataSource and then did a number of experiments like this:

  1. $x = “T” * 1kb  
  2. Write-EventLog -LogName Application -Source MySource $x  
  3. $x = “T” * 10kb  
  4. Write-EventLog -LogName Application -Source MySource $x  
  5. $x = “T” * 100kb  
  6. Write-EventLog -LogName Application -Source MySource $x  

From this I determined that the max size was 32KB.  I added code to only log the first 31KB of a scripblock.  Now any reasonable person would point  out that a 32KB scriptblock is enormous and we’ll never see this condition.

Here is the point – that MAY be true.  But if it isn’t true and it breaks at 3am while some poor soul is trying to stich his datacenter together, then I’ve just made his life even worse.  And so we always code for that poor soul because one day, we will be that guy.  (Remind me to tell you the story about having to sleep on the datacenter floor in a hospital in Memphis between bouts of hand stitching a database together while patients were delayed getting admitted for care.) So here is how that segment came out:

  1. if ($__LogSource)  
  2. {  
  3.   try {  
  4.     if (![System.Diagnostics.EventLog]::SourceExists($__LogSource))  
  5.     {  
  6.       [System.Diagnostics.EventLog]::CreateEventSource($__LogSource, “Application”)  
  7.     }  
  8.   
  9.     # Maximum size of a Eventlog Message is 32KB. We limit to 31KB.  
  10.     $Script = $__ScriptBlock.ToString()  
  11.     if ($Script.Length -ge 31kb)  
  12.     {  
  13.       $Script = $Script.Substring(0, 31kb)  
  14.     }  
  15.     Write-EventLog -LogName Application -Source $__LogSource `  
  16.       -EntryType Information -EventId 1 -Message $(  
  17.       $Message + ” to run `n” + $Script  
  18.     )  
  19.   }  
  20.   catch [Exception] # An exception means you don’t have the privs to create the source  
  21.   {  
  22.     Write-Error -Message “Cannot Write to or Create EventLogSource ($__LogSource)” `  
  23.       -Exception $_.Exception `  
  24.       -Category ResourceUnavailable `  
  25.       -TargetObject $__LogSource `  
  26.       -RecommendedAction “Create LogSource ($__LogSource) using an account with Admin privs” `  
  27.       -ErrorId “CantWriteLog,Measure-Time” `  
  28.       -CategoryReason CantFindorCreateLogSource   
  29.   }  
  30. }  

 

So the point of this blog is that with PowerShell, you can start off with a quick and dirty and evolve it to meet whatever the requirements you have without having to start over from scratch.  It is one of my favorite attributes of PowerShell.  It should be – we designed it to do this.  🙂  So below is the script in the state I left it today.  There is more that can be done but it is fit for the purpose it is going to be used for.  We don’t have to make every script be model of perfection.

  1. <#  
  2. .Synopsis  
  3.    Measure how long something takes  
  4. .DESCRIPTION  
  5.    This script measures how long it takes to run a sequence of code (a ScriptBlock).  
  6.    The message is sent to the Verbose channel so to see it, you either need to have  
  7.    $VerbosePreference set to “Continue” or specify -Verbose.  
  8. .EXAMPLE  
  9.    Measure-Time { get-process } -Verbose  
  10. .EXAMPLE  
  11.    time {get-process} DataCenterUpgrade “It took {0:N3} seconds to run this” -verbose  
  12. #>  
  13. Function Measure-Time  
  14. {  
  15. param(  
  16. #ScriptBlock that you want to measure the timing of  
  17. [Parameter(Position=0, Mandatory=1)]  
  18. [ScriptBlock]$__ScriptBlock,  
  19.   
  20. # Name of the LogSource in the APPLICATION EventLog   
  21. # that these events will show up in.  
  22. #   
  23. # If you don’t provide a value – no log entry will be made.  
  24. [Parameter(Position=1)]  
  25. [String]$__LogSource = $null,  
  26.   
  27. # An alternate format string for the Message  
  28. [Parameter(Position=2)]  
  29. [String]$__FormatString=“Total ElapsedTime: {0:N1} Seconds”  
  30.   
  31. )  
  32.     $_StopWatch = [Diagnostics.Stopwatch]::StartNew()  
  33.     &$__ScriptBlock  
  34.     $_StopWatch.Stop()  
  35.           
  36.     $Message = $__FormatString -f $_StopWatch.Elapsed.TotalSeconds  
  37.     Write-Verbose $Message          
  38.     if ($__LogSource)  
  39.     {  
  40.         try {  
  41.             if (![System.Diagnostics.EventLog]::SourceExists($__LogSource))  
  42.             {  
  43.                 [System.Diagnostics.EventLog]::CreateEventSource($__LogSource, “Application”)  
  44.             }  
  45.   
  46.             # Maximum size of a Eventlog Message is 32KB.  We limit to 31KB.  
  47.             $Script = $__ScriptBlock.ToString()  
  48.             if ($Script.Length -ge 31kb)  
  49.             {  
  50.                 $Script = $Script.Substring(0, 31kb)  
  51.             }  
  52.             Write-EventLog -LogName Application -Source $__LogSource -EntryType Information -EventId 1 -Message $(  
  53.                 $Message + ” to run `n” + $Script  
  54.             )  
  55.         }  
  56.         catch [Exception] # An exception means you don’t have the privs to create the source  
  57.         {  
  58.             Write-Error -Message “Cannot Write to or Create EventLogSource ($__LogSource)” `  
  59.                 -Exception $_.Exception `  
  60.                 -Category ResourceUnavailable `  
  61.                 -TargetObject $__LogSource `  
  62.                 -RecommendedAction “Create LogSource ($__LogSource) using an account with Admin privs” `  
  63.                 -ErrorId “CantWriteLog,Measure-Time” `  
  64.                 -CategoryReason CantFindorCreateLogSource   
  65.         }  
  66.     }  
  67. }  
  68. Set-Alias -Name Time -Value Measure-Time  

I hope sharing my thought process was useful for your scripting.

Cheers!
Jeffrey

4 thoughts on “Evolution of a Script: Timing Operations”

  3. “From this I determined that the max size was 32KB. I added code to only log the first 31KB of a scripblock. Now any reasonable person would point out that a 32KB scriptblock is enormous and we’ll never see this condition.

    Here is the point – that MAY be true. But if it isn’t true and it breaks at 3am while some poor soul is trying to stich his datacenter together, then I’ve just made his life even worse. And so we always code for that poor soul because one day, we will be that guy.”

    This is so true. I’d take your earlier statement a step farther: the difference between a quick and dirty script and a production script is handling errors AND boundary cases properly. It’s easy to write code that works most of the time; writing code that works all of the time takes a bit more attention to detail.

    Reply ↓

  4. What if I learned PowerShell so well so that when I went to a new job I didn’t scare colleagues when I talked about how good and powerful PowerShell is. sounds funny! No, it is what’s happening and to be honest I am afraid loosing my job over it. Still in Love…With my PowerShell – I picked up what PowerShell is designed to do to get people like me to make tools for the job but if that created aggressive competition not sure what to do…Sounds like it is time to come up with some Microsoft official PowerShell exams

    Reply ↓

Leave a Reply

Your email address will not be published. Required fields are marked *