Hey, Scripting Guy! Watch the Stopwatch
The Microsoft Scripting Guys

One of the things I always enjoyed about working in Mexico was the attitude toward time. Everything always got accomplished but nothing was ever really rushed. If my friend Miguel and I were on our way to the office and he suggested we check out a new coffee shop, that's what we did. If we were a few minutes late to the office, what did it matter? We had a nice cup of coffee, enjoyed each other's company, and saw a beautiful sunrise.

As much as I appreciate that lifestyle, things have changed and my personal life has now become quite regimented. I get up at 6:00 A.M., exercise for an hour, take a shower, eat breakfast, and I am in the office by 7:30 A.M. I catch myself looking at my watch dozens of times a day to ensure that I am keeping to my schedule. In Mexico, I did not even bother to wear a watch. Time just never seemed to enter the discussion.

Network administrators and consultants, in contrast, must always be aware of time: We need to schedule backups, compute service availability, and determine system uptime, downtime, and response time. For tracking time, it may be sufficient to click an icon, look at your watch, and count the seconds or minutes until the application opens. But what if you get interrupted during the timing of the event? I don't know about you, but if I get sidetracked during an activity, I tend to forget things.

Even though I could use the rotating bezel on my dive watch to mark the start time, there's still the need to subtract all those numbers—and if I am dealing with interruptions, results might not be reliable. Rather than using a regular watch or even a dive watch, what I really need is a stopwatch, one that tells how long the activity took and remembers how long it took the last time as well. That way, I could get some perspective on what my current results actually mean in terms of performance.

Luckily, the Microsoft .NET Framework has a StopWatch class, which I put to use in a script called Set-StopWatchRecordValues.ps1. This script times an activity and writes the results to the registry. When the script is run on subsequent occasions, it retrieves the previous value from the registry and tells you both the current time and the previous time.

The StopWatch class is part of the System.Diagnostics namespace. It has a static method called StartNew that will create and start a new StopWatch. To call a static method from a .NET Framework class, you put the path to the namespace and the name of the class in square brackets, followed by two colons and the name of the method. In our example, System.Diagnostics is the .NET Framework namespace, and StopWatch is the class. We also need a variable to hold the System.Diagnostics.StopWatch object that is returned by the method:

$sw = [system.diagnostics.stopwatch]::startNew()

Once you do this, you can use the $sw variable to display information about the running StopWatch; for example, you can pipe the results to the Format-List cmdlet to display the value of all the properties contained in the object:

PS C:\> $sw | Format-List -Property *

IsRunning           : True
Elapsed             : 00:00:22.5467175
ElapsedMilliseconds : 22546
ElapsedTicks        : 67472757628

StopWatch has a number of useful methods, which are displayed in Figure 1. The most important is the Stop method because when you use the StartNew static method, the StopWatch object is both created and started at the same time. Therefore, the action you are most likely to take is to stop the StopWatch object in order to see how long the activity took.

In the Set-StopWatchRecordValues.ps1 script, we create four functions to create and manage the StopWatch object and to record the elapsed time in the registry. The first time the script is run, it creates a registry key and informs the user that there is no stored information, as you can see in Figure 2.

Figure 2 The new registry key has no stored information

The script then creates the registry property and stores the current running time in the registry, as shown in Figure 3. When the script is run subsequently, the registry data is retrieved, displayed, and updated, as shown in Figure 4.

Figure 3 The registry key that stores the current running time

Figure 4 Running the script again retrieves, displays, and updates registry data

The script uses a single parameter named $debug, which is a switched parameter, meaning it only does something when it is present. When you run the script with the –debug switch, the script prints out detailed information as found in Figure 5, such as whether the registry key was located, what action the script is getting ready to perform, and when it has finished performing the action.

Figure 5 Running the script with the –debug switch

To create a command-line parameter, you use the Param statement, like so:

Param([switch]$debug)

Following the Param statement, which needs to be the first non-commented line in the script, we create the first function. This function is named Set-StopWatch, and it is used to create and start, or to stop, the StopWatch. The value that is supplied for the function's $action input parameter determines what the function will do. The function declaration is shown here:

Function Set-StopWatch($action)

A switch statement is used to select the action that is performed. This is also where we meet our first debug statement. To write the debug information to the console prompt, we use the Write-Debug cmdlet. The cool thing about the Write-Debug cmdlet is that it automatically formats the text with yellow and black (this is configurable). The other cool thing is that it will only write stuff to the console if you tell it to. By default, Write-Debug does not print out anything to the console. The input variable to the Set-StopWatch function is $action. The Switch statement looks at the value of the $action variable to determine the action to take:

Write-Debug "Set-StopWatch action is $action
 Switch ($action)

Now we need to define the action that will take place. The first action will occur if the value of the $action variable is equal to Start. If it is, we use the StartNew static method from the System.Diagnostic.StopWatch class and store the resulting StopWatch object in the $sw variable. We also create a debug statement indicating that we are starting the timer but, remember, this will only be displayed if the script is started with the –debug switch:

 {
  "Start" { 

Write-Debug "Starting Timer"
              $script:sw = [system.diagnostics
                 .stopwatch]::StartNew() 
             }

When $action matches stop, we write a debug statement that states we are stopping the timer. We then check to see if the registry key exists. If it does, we create a variable named $swv and set it equal to $null. We then print out another debug message:

  "Stop" { 
Write-Debug "Stopping Timer"
               If(Test-Path -path $path)
                  {
                    $swv = $null
Write-Debug "$path was found. Calling Get-StopWatchvalue"

Next, we call the Get-StopWatchvalue function and pass it the $swv variable we just created. In this code, we pass the variable by reference, which means that the function will assign a new value to the variable and we will use it outside of the function that assigns the value to it. To pass the variable by reference, we need to convert $swv to a reference type. We use [ref] to perform this conversion. Note that we had to create the $swv variable earlier because you can't cast the variable to a reference type if it doesn't exist:

                 Get-StopWatchvalue([ref]$swv)
Write-Debug "Get-StopWatchvalue swv was: $($swv)"
                  }

If the registry key does not exist, we write a couple of debug statements, create the $swv variable and set it to null, and then call the New-StopWatchKey function, which creates the registry key:

               Else

                 {
Write-Debug "$path was not found"
                  $swv = $null

Write-Debug "$swv is null. Calling New-StopWatchKey"
                  New-StopWatchKey

After we return from the New-StopWatchKey function, we print another debug statement and call the Get-StopWatchvalue function. We also pass the $swv variable by reference ($swv will be used later to display the data that was retrieved from the registry):

Write-Debug "Obtaining default value from get-StopWatchvalue"
                 et-StopWatchvalue([ref]$swv)
                 }

Now we need to stop the StopWatch. We first use another debug statement to print out a stop message, and then we call the Stop method from the StopWatch object stored in the $sw variable. After we have stopped the StopWatch, we need to convert the System.TimeSpan object that is obtained via the Elapsed property to a string so we can store its value in the registry. We pass the string representation of the timespan object to the Set-StopWatchValue function as seen here:

Write-Debug "Stopping the stop watch"
               $script:sw.Stop() 
Write-Debug "Converting stop watch to string, and calling
 Set-StopWatchValue"
                   Set-StopWatchValue($script:
                      sw.Elapsed.toString())

Now we are ready to print the output to the console. The first thing we do is tell how long it took for the command to run. We use the script-scoped $sw variable and obtain the Elapsed property. A subexpression is used to force the evaluation of the Elapsed property to return the timespan object.

This may seem a bit confusing until you understand there are two kinds of string characters in Windows PowerShell. The first are literal strings, which are represented with single quotation marks. With a literal string, what you see is what you get. This means that a variable will not be expanded inside single quotation marks:

PS C:\> $a = "this is a string"
PS C:\> "This is what is in $a"
This is what is in $a

When you use expanding strings, represented by double quotation marks, the value of the variable is expanded and printed out:

PS C:\> $a = "this is a string"
PS C:\> "This is what is in $a"
This is what is in this is a string

While frustrating at first, this can be used to your advantage to avoid concatenating strings and variables. When you are aware of the two strings, you can use the backtick character to suppress variable expansion when desired:

PS C:\> $a = "this is a string"
PS C:\> "This is what is in "$a: $a"
This is what is in $a: this is a string

If you did not have expanding strings, you would need to concatenate the output like this:

PS C:\> $a = "this is a string"
PS C:\> "This is what is in $a: " + $a
This is what is in $a: this is a string

So what does this have to with our code? When an object is expanded in an expanding string, it will tell you the name of the object. If you want to see the value, you need to create a subexpression by placing the object in parentheses and placing a dollar sign in front of it. This will force the evaluation of the object and return the default property to the command line as shown here:

PS C:\> "$sw.Elapsed"
System.Diagnostics.Stopwatch.Elapsed
PS C:\> "$($sw.Elapsed)"
00:00:07.5247519

In our output, we print a message that displays how long the command took, as well as the value that is stored in the $swv variable as shown here:

"The command took $($script:sw.Elapsed)"
"Previous command took: " + $swv

It is always a best practice when using the Switch statement to create a default action. If the script is not running with the –debug switch, the script will print out the value of the $action variable and tell the user to use either Start or Stop. If it is running with the debug switch, several different lines are printed. In any case, the script will exit by calling the exit command, as shown here:

   Default {
                 if(!$debug) {"$action is not understood. Specify Start / Stop"} 
Write-Debug "Entering default action. $action was specified."
Write-Debug "Action value must be either Start or Stop"
Write-Debug "Exiting script now"
                  Exit
               }
} #end Switch
} #end Set-StopWatch

Now we come to the New-StopWatchKey function, which is called when the script detects that the scripting registry key has not yet been created. The first thing the New-StopWatchKey function does is print out a debug message. It then uses the New-Item cmdlet to create the registry key. The resulting message from this is piped to the Out-Null cmdlet to avoid cluttering the display.

Another debug message is printed out, and then the registry property is created to hold the previous run time. To do this, we use the New-ItemProperty cmdlet. The resulting message from this cmdlet is also sent to the Out-Null cmdlet. We print out one more debug message and leave the function:

Function New-StopWatchKey()
{
 Write-Debug "Inside New-StopWatchKey. Creating new item $path"
New-Item -path $path -force | 
out-null
Write-Debug "Creating new item property $property"
New-ItemProperty -Path $path "
-Name $property -PropertyType string -value "no data" | 
 out-null
Write-Debug "Leaving New-StopWatchkey"
} #end New-StopWatchKey

Now we need to create the Get-StopWatchvalue function to read the data stored in the registry and assign the data to the $swv reference variable. To do this, we first print out a couple of debug messages, and then use the Get-ItemProperty cmdlet to create a custom Windows PowerShell object that we store in the $swValue variable. As you can see here, there are a number of properties contained in the object:

PS C:\> $swValue = Get-ItemProperty -Path HKCU:\Scripting\Stopwatch
PS C:\> $swValue

PSPath          : Microsoft.PowerShell.Core\Registry::HKEY_CURRENT_USER\Scripting\Stopwatch
PSParentPath    : Microsoft.PowerShell.Core\Registry::HKEY_CURRENT_USER\Scripting
PSChildName     : Stopwatch
PSDrive         : HKCU
PSProvider      : Microsoft.PowerShell.Core\Registry
PreviousCommand : 00:00:00.3153793

You do not have to use the intermediate variable to obtain the previous value property. You can use parentheses and query the property directly. This can be a bit confusing, but the syntax is valid, as you can see:

PS C:\> (Get-ItemProperty -Path HKCU:\Scripting\Stopwatch).PreviousCommand
00:00:00.3153793

After we have the custom object, we query the PreviousCommand property and assign it to the value property of the $swv reference type variable. A couple more debug statements and we are done with the Get-StopWatchvalue function:

Function Get-StopWatchvalue([ref]$swv)
{
Write-Debug "Inside Get-StopWatchvalue."
Write-Debug "Obtaining $path\$property"
$swValue = Get-ItemProperty -Path $path "
  -Name $property
$swv.value = $swValue.PreviousCommand
Write-Debug "Value of "$swv is $($swv.value)"
Write-Debug "Leaving Get-StopWatchvalue"
} #end Get-StopWatchvalue

Next, we want to write to the registry the amount of time the command took so we create the Set-StopWatchvalue function. This function accepts the value to be written to the registry in the variable $newSwv. We write a couple of debug statements, and then call the Set-ItemProperty cmdlet, giving it the path stored in the $path variable, the name of the registry property stored in the $property variable, and the value that is stored in the $newSwv variable. We then print out one more debug message, and leave the Set-StopWatchValue function:

Function Set-StopWatchvalue($newSwv)
{
Write-Debug "Inside Set-StopWatchvalue"
Write-Debug "setting $path\$property to $newSwv"
Set-ItemProperty -Path $path "
-Name $property -Value $newSwv
Write-Debug "Leaving Set-StopWatchvalue"
} #end Set-StopWatchvalue

Now we have created all the functions required for the script. The entry point of the script first tests to see if the $debug variable is present. If it is, the script was run with the –debug switch and we change the value of the $DebugPreference automatic variable to "continue." By default, the $DebugPreference variable is set to silently continue, which means no debug messages will be displayed by the Write-Debug cmdlet.

In our script, we want to store the StopWatch times in a registry key under the HKEY_Current_User hive named Scripting\Stopwatch. We use a property named PreviousCommand. Each of these is assigned to the appropriate variables. The first thing we do after initializing the variables is call the Set-StopWatch function with Start for the action. After that function runs, we call the Get-Process cmdlet:

if($debug) { $DebugPreference = "continue" }
$path = "HKCU:\Scripting\Stopwatch"
$property = "PreviousCommand"
Set-StopWatch "Start"
Get-Process

If you are using this script to time various activities, this is where you would add what you need. You could even call a script at this point or include any number of commands to suit your needs.

If the $debug variable does not exist, the script is running in normal mode. In that case, we don't need to see the results of calling the Get-Process cmdlet on the screen because we are only interested in timing the activity. We therefore use the not operator (the exclamation mark, bat and ball, whatever you want to call it) to indicate that if there's no debug variable, we'll clear the screen using the Clear-Host Windows PowerShell function. Finally, we call the Set-StopWatch function with the Stop action to bring things to a halt:

if(!$debug) {Clear-Host}
Set-StopWatch "Stop"

Figure 6 shows the complete Set-StopWatchRecordValues.ps1 script.

Figure 6 Set-StopWatchRecordValues.ps1

Param([switch]$debug)
Function Set-StopWatch($action)
{
Write-Debug “Set-StopWatch action is $action”
 Switch ($action)
 {
  “Start” {
Write-Debug “Starting Timer”
               $script:sw = [system.diagnostics.stopwatch]::StartNew()
            }
  “Stop” {
Write-Debug “Stopping Timer”
               If(Test-Path -path $path)
                  {
                    $swv = $null
Write-Debug “$path was found. Calling Get-StopWatchvalue”
                    Get-StopWatchvalue([ref]$swv)
Write-Debug “Get-StopWatchvalue swv was: $($swv)”
                   }
               Else
                 {
Write-Debug “$path was not found”
                 $swv = $null
Write-Debug “$swv is null. Calling New-StopWatchKey”
                 New-StopWatchKey
Write-Debug “Obtaining default value from get-StopWatchvalue”
                 Get-StopWatchvalue([ref]$swv)
                }
Write-Debug “Stopping the stop watch”
               $script:sw.Stop()
Write-Debug “Converting stop watch to string, and calling Set-StopWatchValue”
               Set-StopWatchValue($script:sw.Elapsed.toString())
               “The command took $($script:sw.Elapsed)”
               “Previous command took: “ + $swv
              }
      Default {
                  if(!$debug) {“$action is not understood. Specify Start / Stop”}
Write-Debug “Entering default action. $action was specified.”
Write-Debug “Action value must be either Start or Stop”
Write-Debug “Exiting script now”
                 Exit
              }
 } #end Switch
} #end Set-StopWatch

Function New-StopWatchKey()
{
Write-Debug “Inside New-StopWatchKey. Creating new item $path”
 New-Item -path $path -force |
 out-null
Write-Debug “Creating new item property $property”
 New-ItemProperty -Path $path `
 -Name $property -PropertyType string -value “no data” |
 out-null
Write-Debug “Leaving New-StopWatchkey”
} #end New-StopWatchKey

Function Get-StopWatchvalue([ref]$swv)
{
Write-Debug “Inside Get-StopWatchvalue.”
Write-Debug “Obtaining $path\$property”
 $swValue = Get-ItemProperty -Path $path `
  -Name $property
 $swv.value = $swValue.PreviousCommand
Write-Debug “Value of `$swv is $($swv.value)”
Write-Debug “Leaving Get-StopWatchvalue”
} #end Get-StopWatchvalue

Function Set-StopWatchvalue($newSwv)
{
Write-Debug “Inside Set-StopWatchvalue”
Write-Debug “setting $path\$property to $newSwv”
 Set-ItemProperty -Path $path `
 -Name $property -Value $newSwv
Write-Debug “Leaving Set-StopWatchvalue”
} #end Set-StopWatchvalue

# *** entry point ***

if($debug) { $DebugPreference = “continue” }
$path = “HKCU:\Scripting\Stopwatch”
$property = “PreviousCommand”
Set-StopWatch “Start”
Get-Process
if(!$debug) {Clear-Host}
Set-StopWatch “Stop”

I hope you have enjoyed this excursion into the StopWatch class. Come over to the TechNet Script Center and check out our daily "Hey, Scripting Guy!" articles.

Ed Wilson is a well-known scripting expert. He has written and published eight books on the Microsoft Press imprint, including five on Microsoft Windows scripting, and is currently working on a Windows PowerShell best practices book. Ed holds more than 20 industry certifications, including Microsoft Certified Systems Engineer (MCSE) and Certified Information Systems Security Professional (CISSP). In his spare time he enjoys woodworking, underwater photography, and scuba diving. And tea.

Craig Liebendorfer is a wordsmith and longtime Microsoft Web editor. Craig still can't believe there's a job that pays him to work with words every day. One of his favorite things is irreverent humor, so he should fit right in here. He considers his greatest accomplishment in life to be his magnificent daughter.