# encoding: ascii
# api: powershell
# title: Trace-Message
# description: A trace/logging system that wraps Write-Verbose, Write-Debug or Write-Warning to add timestamps and invocation source to the output, as well as allowing complicated messages to be calculated only when the output will actually be displayed.
# version: 1.25
# type: function
# author: Joel Bennett
# license: CC0
# function: Trace-Message
# x-poshcode-id: 6457
# x-archived: 2016-07-29T20:11:45
# x-published: 2016-07-26T05:15:00
#
#
function Trace-Message {
<#
.Synopsis
Wrap Verbose, Debug, or Warning output with command profiling trace showing script line and time elapsed
.Description
Creates a stopwatch that tracks the time elapsed while a script runs, and adds caller position and time to the output
.Example
foreach($i in 1..20) { sleep -m 50; Trace-Message "Progress $i" }
Demonstrates the simplest use of Trace-Message to add a duration timestamp to the message.
.Example
function Test-Trace {
[CmdletBinding()]param()
foreach($i in 1..20) {
$i
Trace-Message {
sleep -m 50; # just to be sure you can tell this is slow
$ps = (Get-Process | sort PM -Desc | select -first 2)
"Memory hog {1} using {0:N2}GB more than next process" -f (($ps[0].WS -$ps[1].WS) / 1GB), $ps[0].Name
} @PSBoundParameters
}
}
Demonstrates how using a scriptblock can avoid calculation of complicated output when -Verbose is not set. In this example, "Test-Trace" by itself will output 1-20 in under 20 miliseconds, but with verbose output, it can take over 1.25 seconds
#>
[CmdletBinding(DefaultParameterSetName="Precalculated")]
param(
# The message to write
[Parameter(Mandatory=$true,ValueFromPipeline=$true,ValueFromPipelineByPropertyName=$true,ParameterSetName="Precalculated",Position=0)]
[Parameter(Mandatory=$true,ValueFromPipeline=$true,ValueFromPipelineByPropertyName=$true,ParameterSetName="PrecalculatedWarningOutput",Position=0)]
[Parameter(Mandatory=$true,ValueFromPipeline=$true,ValueFromPipelineByPropertyName=$true,ParameterSetName="PrecalculatedDebugOutput",Position=0)]
[PSObject]$Message,
# A scriptblock which, when evaluated, will output a message to write
[Parameter(Mandatory=$true,ParameterSetName="DeferredTemplate",Position=0)]
[Parameter(Mandatory=$true,ParameterSetName="DeferredTemplateWarningOutput",Position=0)]
[Parameter(Mandatory=$true,ParameterSetName="DeferredTemplateDebugOutput",Position=0)]
[ScriptBlock]$DeferredTemplate,
# When set, output to the warning stream instead of verbose
[Parameter(Mandatory=$true,ParameterSetName="PrecalculatedWarningOutput")]
[Parameter(Mandatory=$true,ParameterSetName="DeferredTemplateWarningOutput")]
[Alias("AsWarning")]
[switch]$WarningOutput,
# When set, output to the debug stream instead of verbose
[Parameter(Mandatory=$true,ParameterSetName="PrecalculatedDebugOutput")]
[Parameter(Mandatory=$true,ParameterSetName="DeferredTemplateDebugOutput")]
[switch]$DebugOutput,
# Reset the timer to time the next block from zero
[switch]$ResetTimer,
# Clear out the timer completely after this output
# When you explicitly pass a Stopwatch, you can pass this flag (only once) to stop and remove it
[switch]$KillTimer,
# A custom string overrides the automatic formatting which changes depending on how long the duration is
[string]$ElapsedFormat,
# Supports passing in an existing Stopwatch (running or not)
[Diagnostics.Stopwatch]$Stopwatch
)
begin {
if($Stopwatch) {
${Script:Trace Message Timer} = $Stopwatch
${Script:Trace Message Timer}.Start()
}
if(-not ${Trace Message Timer}) {
${global:Trace Message Timer} = New-Object System.Diagnostics.Stopwatch
${global:Trace Message Timer}.Start()
# When no timer is provided...
# Assume the timer is for "run" and
# Clean up automatically at the next prompt
$PreTraceTimerPrompt = $function:prompt
$function:prompt = {
if(${global:Trace Message Timer}) {
${global:Trace Message Timer}.Stop()
Remove-Variable "Trace Message Timer" -Scope global -ErrorAction SilentlyContinue
}
& $PreTraceTimerPrompt
${function:global:prompt} = $PreTraceTimerPrompt
}.GetNewClosure()
}
if($ResetTimer -or -not ${Trace Message Timer}.IsRunning)
{
${Trace Message Timer}.Restart()
}
# Note this requires a host with RawUi
$w = $Host.UI.RawUi.BufferSize.Width
}
process {
if(($WarningOutput -and $WarningPreference -eq "SilentlyContinue") -or
($DebugOutput -and $DebugPreference -eq "SilentlyContinue") -or
($VerbosePreference -eq "SilentlyContinue")) { return }
[string]$Message = if($DeferredTemplate) {
($DeferredTemplate.InvokeReturnAsIs(@()) | Out-String -Stream) -join "`n"
} else { "$Message" }
$Message = $Message.Trim()
$Location = if($MyInvocation.ScriptName) {
$Name = Split-Path $MyInvocation.ScriptName -Leaf
"${Name}:" + "$($MyInvocation.ScriptLineNumber)".PadRight(4)
} else { "" }
$Tail = $(if($ElapsedFormat) {
"{0:$ElapsedFormat}" -f ${Trace Message Timer}.Elapsed
}
elseif(${Trace Message Timer}.Elapsed.TotalHours -ge 1.0) {
"{0:h\:mm\:ss\.ffff}" -f ${Trace Message Timer}.Elapsed
}
elseif(${Trace Message Timer}.Elapsed.TotaMinutes -ge 1.0) {
"{0:mm\m\ ss\.ffff\s}" -f ${Trace Message Timer}.Elapsed
}
else {
"{0:ss\.ffff\s}" -f ${Trace Message Timer}.Elapsed
}).PadLeft(12)
$Tail = $Location + $Tail
# "WARNING: ".Length = 10
$Length = ($Message.Length + 10 + $Tail.Length)
# Twenty-five is a minimum 15 character message...
$PaddedLength = if($Length -gt $w -and $w -gt (25 + $Tail.Length)) {
[string[]]$words = -split $message
$short = 10 # "VERBOSE: ".Length
$count = 0 # Word count so far
$lines = 0
do {
do {
$short += 1 + $words[$count++].Length
} while (($words.Count -gt $count) -and ($short + $words[$count].Length) -lt $w)
$Lines++
if(($Message.Length + $Tail.Length) -gt ($w * $lines)) {
$short = 0
}
} while($short -eq 0)
$Message.Length + ($w - $short) - $Tail.Length
} else {
$w - 10 - $Tail.Length
}
$Message = "$Message ".PadRight($PaddedLength, "$([char]8331)") + $Tail
if($WarningOutput) {
Write-Warning $Message
} elseif($DebugOutput) {
Write-Debug $Message
} else {
Write-Verbose $Message
}
}
end {
if($KillTimer -and ${Trace Message Timer}) {
${Trace Message Timer}.Stop()
Remove-Variable "Trace Message Timer" -Scope Script -ErrorAction Ignore
Remove-Variable "Trace Message Timer" -Scope Global -ErrorAction Ignore
}
}
}