Fun With PowerShell Write-Verbose

Introduction

In my previous post, Fun With the PowerShell Switch Parameter, I introduced the use of switches with PowerShell functions. We learned how they work, and how to create your own. For all functions, PowerShell creates a set of switches that are just “built in” to PowerShell. You do not have to explicitly create these yourself, you can simply use them and implement them within your own functions.

Two of the most used are -Verbose and -Debug. When used with the Write-Verbose and Write-Debug cmdlets they will display informational messages to the user of your functions. In this post, we’ll focus on the Verbose switch. The next post in the series will examine the Debug switch.

We’ll take a deeper look at Verbose in a moment, but first let me mention that for all of the examples, we’ll display the code, then under it the result of our code. In this article I’ll be using PowerShell Core, 7.1.4, and VSCode. The examples should work in PowerShell 5.1 in the PowerShell IDE, although they’ve not been tested there.

To run a snippet of code highlight the lines you want to execute, then in VSCode press F8 or in the IDE F5. You can display the contents of any variable by highlighting it and using F8/F5.

Write-Verbose

Messages displayed using the -Verbose switch are intended for the users. It can advise a user of long running processes, or let the user know a function is indeed being executed. Let’s take a look at a function we’ll use for this demo.

function Show-FileInfo ()
{
  [CmdletBinding()]
  param ( [Parameter (ValueFromPipeline)]
          $file
        )

  process
  {
    $retVal = "$($file.Name) is {0:N0} bytes long." -f $file.Length
    $retVal
  }

}

The purpose of this function is to take a stream of files from the pipeline, then display the file name and the file size. It’s extremely simple but will serve for this blog post. If you need more info on how pipelined functions work, please see my recent post Fun With PowerShell Pipelined Functions. That post will explain the structure of the function, including the begin, process and end blocks.

Let’s run this function. First, highlight the function and execute it to get it in memory. Then let’s call the function.

Get-ChildItem | Show-FileInfo

Result:

01 - Cmdlets.ps1 is 3,732 bytes long.
02 - Providers.ps1 is 1,819 bytes long.
03 - Variables.ps1 is 4,717 bytes long.
04 - Strings.ps1 is 7,970 bytes long.
05 - Arrays and Hashtables.ps1 is 8,486 bytes long.
06 - Logic Branching and Looping.ps1 is 4,315 bytes long.
07 - Functions.ps1 is 9,574 bytes long.
08 - Classes.ps1 is 6,210 bytes long.
09 - Examples.ps1 is 3,125 bytes long.
Company.csv is 9,694 bytes long.
Company.json is 19,479 bytes long.
ReadMe.md is 1,115 bytes long.

So far so good, you can see the files I have in my current folder (obviously your list of files will vary). Now let’s say we want to let the user know when the function starts and ends, so the user can get an idea of how long it will take to execute. Most of the time our function runs in an automated fashion so we don’t need this, however there may be times when a user wants to manually run it so they can get execution times.

We can modify our function to use the Write-Verbose cmdlet to display this message when the built in -Verbose switch is used. First, we’ll add a begin block to our function to show the start time.

begin
  {
    $fn = "$($PSCmdlet.MyInvocation.MyCommand.Name)"
    $st = Get-Date
    Write-Verbose @"
  `r`n  Function: $fn
  Starting at $($st.ToString('yyyy-MM-dd hh:mm:ss tt'))
"@
  }

The first thing we do is get the function name. PowerShell has a built in variable called $PSCmdlet which has information about the code currently being executed. It has an object property called MyInvocation, which has an object property named MyCommand. This has a property called Name which holds the name of the function currently being executed.

While this seems a bit more complicated than just keying in $fn = 'Show-FileName', it actually leverages code reuse. I can paste this into any function and continue, without the need to update anything.

Next I capture the current date and time into a variable called $st, short for start time.

The call to Write-Verbose comes next. By default, when a Write-Verbose is executed, it displayes the text VERBOSE: followed by the message, such as:

VERBOSE: Your Message Here

In my example though I want to display a multi line message. The first line will hold the name of the function, the second will be the start time. To accomplish this I am using a here string. If you aren’t familiar with here strings, see my post from July 12, 2021 named Fun With PowerShell Strings.

In the here string I start with the characters `r`n. This will send a carriage return – line feed to the here string, so the VERBOSE: will appear on a line by itself. I then add two spaces so the line with the function name will be indented two spaces. Not necessary, but I think it makes it more readable.

The next line is the starting time, also indented two spaces. Here I take the start time and convert it to a string. Into the ToString function I pass in a date format string to display the current date and time. This will produce year-month-day hour:minute:second, with the tt becoming AM or PM. Finally I close out the here string as well as the process block.

As is, this code could be copy and pasted into any function without modification, ready to use. You could even go so far as to make it a snippet in VSCode, I have a project on GitHub, VSCode_User_Snippets that explains how to create user snippets in VSCode. It was written to target implementing MarkDown snippets, but I also included my default PowerShell snippets. Note that the PowerShell IDE used with PowerShell 5.1 also allows for reusable code snippets.

OK, we’ve handled the message we want to show when the function starts. Now we’ll add an end block to display the ending time.

end
  {
    $et = Get-Date
    Write-Verbose @"
  `r`n  Function: $fn
  Finished at $($et.ToString('yyyy-MM-dd hh:mm:ss tt'))
"@
  }

Since I already had the function name in the $fn variable I didn’t have to get it again. I just grab the current time into the variable $et (for end time) and display it as I did in the opening.

For reference here is the function again with the new blocks added.

function Show-FileInfo ()
{
  [CmdletBinding()]
  param ( [Parameter (ValueFromPipeline)]
          $file
        )

  begin
  {
    $fn = "$($PSCmdlet.MyInvocation.MyCommand.Name)"
    $st = Get-Date
    Write-Verbose @"
  `r`n  Function: $fn
  Starting at $($st.ToString('yyyy-MM-dd hh:mm:ss tt'))
"@
  }

  process
  {
    $retVal = "$($file.Name) is {0:N0} bytes long." -f $file.Length
    $retVal
  }

  end
  {
    $et = Get-Date
    Write-Verbose @"
  `r`n  Function: $fn
  Finished at $($et.ToString('yyyy-MM-dd hh:mm:ss tt'))
"@
  }
}

If I run this, you'll see I get the exact same results I did the first time.

Get-ChildItem | Show-FileInfo

Result:

01 - Cmdlets.ps1 is 3,732 bytes long.
02 - Providers.ps1 is 1,819 bytes long.
03 - Variables.ps1 is 4,717 bytes long.
04 - Strings.ps1 is 7,970 bytes long.
05 - Arrays and Hashtables.ps1 is 8,486 bytes long.
06 - Logic Branching and Looping.ps1 is 4,315 bytes long.
07 - Functions.ps1 is 9,574 bytes long.
08 - Classes.ps1 is 6,210 bytes long.
09 - Examples.ps1 is 3,125 bytes long.
Company.csv is 9,694 bytes long.
Company.json is 19,479 bytes long.
ReadMe.md is 1,115 bytes long.

So how do I get the verbose messages to display? Well all I have to do is add the -Verbose switch to the call.

Get-ChildItem | Show-FileInfo -Verbose

Result:

VERBOSE:   
  Function: Show-FileInfo
  Starting at 2021-08-15 07:28:26 PM
01 - Cmdlets.ps1 is 3,732 bytes long.
02 - Providers.ps1 is 1,819 bytes long.
03 - Variables.ps1 is 4,717 bytes long.
04 - Strings.ps1 is 7,970 bytes long.
05 - Arrays and Hashtables.ps1 is 8,486 bytes long.
06 - Logic Branching and Looping.ps1 is 4,315 bytes long.
07 - Functions.ps1 is 9,574 bytes long.
08 - Classes.ps1 is 6,210 bytes long.
09 - Examples.ps1 is 3,125 bytes long.
Company.csv is 9,694 bytes long.
Company.json is 19,479 bytes long.
ReadMe.md is 1,115 bytes long.
VERBOSE:   
  Function: Show-FileInfo
  Finished at 2021-08-15 07:28:26 PM

Simply by adding the -Verbose switch, it now displays the text passed into any Write-Verbose cmdlets you coded. If you look at our param block, you won’t see the Verbose switch declared, as we had to in the previous article Fun With the PowerShell Switch Parameter.

PowerShell automatically adds the Verbose switch to every advanced function you author. You don’t have to do anything special. If PowerShell sees you’ve added the switch when you (or a user) runs your function, it will automatically execute any Write-Verbose cmdlets for you.

Taking It to the Next Level

As is, this function requires our user to manually calculate the run time by comparing the start and end times. But PowerShell developers are a courteous bunch, and so we’ll take care of this for them.

Let’s update the end block to perform the calculation.

  end
  {
    $et = Get-Date

    $rt = $et - $st  # Run Time

    # Format the output time
    if ($rt.TotalSeconds -lt 1)
      { $elapsed = "$($rt.TotalMilliseconds.ToString('#,0.0000')) Milliseconds" }
    elseif ($rt.TotalSeconds -gt 60)
      { $elapsed = "$($rt.TotalMinutes.ToString('#,0.0000')) Minutes" }
    else
      { $elapsed = "$($rt.TotalSeconds.ToString('#,0.0000')) Seconds" }


    Write-Verbose @"
  `r`n  Function: $fn
  Finished at $($et.ToString('yyyy-MM-dd hh:mm:ss tt'))
  Elapsed Time $elapsed
"@
  }

After getting my end time, I subtract the start time from the end time, and place it in the $rt variable, short for run time. This will produce a variable that is a datetime datatype.

A PowerShell datetime datatype has some very useful methods. The first we’ll use is TotalSeconds, which indicates how many seconds are in our variable. In the if statement, check to see if the run time seconds is less than 1. If so, it uses another property TotalMilliseconds that (obviously) returns the total number of milliseconds in the run time variable. It converts it to a string, and we pass in a string format so we get a nice output. Finally it appends the text Milliseconds so the user will now what time unit they are dealing with, and places it all in a variable $elapsed.

The elseif is similar. If the total seconds exceeds 60, we’ll display the run time in minutes. The else script block covers the case when the elapsed time is between 1 and 60 seconds.

Finally we add a third line to the here string passed into Write-Verbose.

Highlight the entire function and execute it so the new version is in memory. Then call the function using the Verbose switch.

Get-ChildItem | Show-FileInfo -Verbose

Result:

VERBOSE:   
  Function: Show-FileInfo
  Starting at 2021-08-15 07:59:39 PM
01 - Cmdlets.ps1 is 3,732 bytes long.
02 - Providers.ps1 is 1,819 bytes long.
03 - Variables.ps1 is 4,717 bytes long.
04 - Strings.ps1 is 7,970 bytes long.
05 - Arrays and Hashtables.ps1 is 8,486 bytes long.
06 - Logic Branching and Looping.ps1 is 4,315 bytes long.
07 - Functions.ps1 is 9,977 bytes long.
08 - Classes.ps1 is 6,210 bytes long.
09 - Examples.ps1 is 3,125 bytes long.
Company.csv is 9,694 bytes long.
Company.json is 19,479 bytes long.
ReadMe.md is 1,115 bytes long.
VERBOSE:   
  Function: Show-FileInfo
  Finished at 2021-08-15 07:59:39 PM
  Elapsed Time 19.9018 Milliseconds

As you can see, these few extra lines of code provides a more professional looking output, not to mention accurate. The user will not be forced to manually calculate times.

And don’t forget you can place these into code snippets for fast and easy use. As constructed both the opening and closing sections can simply be inserted without modification. Again, see my GitHub project, VSCode_User_Snippets for examples on using code snippets in Visual Studio Code.

Conclusion

In this post we saw how the built in -Verbose switch works along with the companion Write-Verbose. This can provide a useful tool to keep users appraised of extra, “meta” information such as run times without obscuring the output of the function when it is used in normal circumstances.

In the next blog post we’ll look at the counterpart for verbose, -Debug and it’s Write-Debug cmdlet.

If you want to learn more about PowerShell, check out my Pluralsight course PowerShell 7 Quick Start for Developers on Linux, macOS and Windows, one of many PowerShell courses I have on Pluralsight. All of my courses are linked on my About Me page.

If you don’t have a Pluralsight subscription, just go to my list of courses on Pluralsight . At the top is a Try For Free button you can use to get a free 10 day subscription to Pluralsight, with which you can watch my courses, or any other course on the site.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s