Custom TypeName Slow Output

PowerShell Help
1

I have a module with a function that collects the firmware versions on HP servers using the HPRESTCmdlets module found on the gallery. The function assigns the object a custom typename of ‘Hardware.Firmware’ and I am using a ps1xml for custom viewing. The function consists of a begin, process, and end scriptblock. When running the function against a set of objects (via foreach) the first object is always delayed in the output to the console, it actually is displayed after the END block runs. Every sequential object runs as expected. I also receive the same delay if running against a single object. If I remove the custom typename, the first object has no delay and is process correctly. Any ideas on why there is a delay on processing the first object when using a custom type and how can I avoid it? Here is the code for the function:

function Get-HPFirmware {
	[CmdletBinding()]
	param (
		[Parameter(Mandatory = $true, Position = 0)]
		[Alias('Name', 'Server', 'Ip')]
		[string]$iLoName,
		
		[Parameter(Mandatory = $true)]
		[ValidateNotNullorEmpty()]
		[Alias('User')]
		[System.Management.Automation.PSCredential][System.Management.Automation.Credential()]
		$Credential,
		
		[switch]$IgnoreCertFailures
	)
	
	BEGIN {
		$DefaultVariables = $(Get-Variable).Name
		try {
			Import-Module -Name HPRESTCmdlets -Force -ErrorAction Stop -Verbose:$false
		} catch {
			throw
		}
		
		Write-Verbose -Message "Splatting parameters for Connect-HPREST"
		$ConnectParams = @{
			'Address'  = $PSBoundParameters['iLoName']
			'Credential' = $PSBoundParameters['Credential']
		}
		
		if ($PSBoundParameters.ContainsKey('IgnoreCertFailures')) {
			$ConnectParams.DisableCertificateAuthentication = $true
		}
	}
	PROCESS {
		try {
			Write-Verbose -Message "Connecting to $($ConnectParams['Address'])"
			$Session = Connect-HPREST @ConnectParams -ErrorAction Stop
		} catch {
			throw
		}
		
		try {
			$Systems = Get-HPRESTDataRaw -Href '/rest/v1/Systems' -Session $Session -ErrorAction Stop
			foreach ($Sys in $Systems.links.member.href) {
				$Data = Get-HPRESTDataRaw -Href $Sys -Session $Session -ErrorAction Stop
				$FirmwareUri = ($Data.Oem.Hp.links.PSObject.Members | Where-Object -FilterScript { $_.Name -match 'Firmware' }).Value.href
				Write-Verbose -Message "Firmware Uri ($FirmwareUri) discovered"
				if ($FirmwareUri) {
					$FirmwareData = Get-HPRESTDataRaw -Href $FirmwareUri -Session $Session -ErrorAction Stop
					if ($FirmwareData) {
						$Firmware = $FirmwareData.Current | ForEach-Object -Process {
							($_.PSObject.Members | Where-Object -FilterScript { $_.MemberType -eq 'NoteProperty' }).Value
						}
						Write-Verbose -Message "$($Firmware.Count) components discovered"
					} else {
						Write-Warning -Message "No firmware data available via $FirmwareUri for $($PSBoundParameters['iLoName'])"
						break
					}
				} else {
					Write-Warning -Message "Unable to locate the firmware uri"
					break
				}
				
				$PCIDevicesUri = ($Data.Oem.Hp.links.PSObject.Members | Where-Object -FilterScript { $_.Name -match 'PCIDevices' }).Value.href
				Write-Verbose -Message "PCI Device Uri ($PCIDevicesUri) discovered"
				if ($PCIDevicesUri) {
					$PCIData = Get-HPRESTDataRaw -Href $PCIDevicesUri -Session $Session -ErrorAction Stop
					if (!$PCIData) {
						Write-Warning -Message "No PCI device data available via $PCIDevicesUri for $($PSBoundParameters['iLoName'])"
						break
					}
					Write-Verbose -Message "$($PCIData.Items.Count) devices discovered"
				} else {
					Write-Warning -Message "Unable to locate the PCI device uri"
					break
				}
				
				foreach ($i in $Firmware) {
					if ($i.UEFIDevicePaths) {
						$Device = $PCIData.Items | Where-Object -FilterScript { $_.UEFIDevicePath -eq $i.UEFIDevicePaths }
						$Props = @{
							'ElementName'    = $i.Name
							'Location'	     = $i.Location
							'VersionString'  = $i.VersionString
							'FQDD'		     = if ($i.Name -match 'FC') { $Device.StructuredName -replace "^\w{3}", "FC" } else { $Device.StructuredName -replace "\s", "" }
							'DeviceId'	     = $Device.DeviceId
							'SubDeviceId'    = $Device.SubsystemDeviceID
							'VendorId'	     = $Device.VendorID
							'SubVendorId'    = $Device.SubsystemVendorID
						}
					} else {
						$Props = @{ }
						switch -wildcard ($i.Name) {
							'*Power Supply*' {
								$Props.ElementName = "$($i.Name).$($i.Location)"
								$Props.Location = $i.Location
								$Props.VersionString = $i.VersionString
								$Props.FQDD = "PSU.$($i.Location -replace '\s', '')"
							}
							'*iLo*' {
								$Props.ElementName = "Integrated Lights Out"
								$Props.Location = $i.Location
								$Props.VersionString = $i.VersionString.Split(' ')[0]
								$Props.FQDD = "$($i.Name).$($i.Location -replace '\s', '')"
							}
							'*System ROM*' {
								$Props.ElementName = $i.Name
								$Props.Location = $i.Location
								$Props.VersionString = $i.VersionString.Split(' ')[1]
								$Props.FQDD = "BIOS.$($i.Location -replace '\s', '')"
							}
							'*Intelligent*' {
								$Props.ElementName = $i.Name
								$Props.Location = $i.Location
								$Props.VersionString = $i.VersionString
								$Props.FQDD = "DriverPack.$($i.Location -replace '\s', '')"
							}
							'*Power Management*' {
								$Props.ElementName = $i.Name
								$Props.Location = $i.Location
								$Props.VersionString = $i.VersionString
								$Props.FQDD = "DriverPack.$($i.Location -replace '\s', '')"
							} '*Server Platform*' {
								$Props.ElementName = $i.Name
								$Props.Location = $i.Location
								$Props.VersionString = $i.VersionString
								$Props.FQDD = "SPS.$($i.Location -replace '\s', '')"
							} '*Logic Device*' {
								$Props.ElementName = $i.Name
								$Props.Location = $i.Location
								$Props.VersionString = $i.VersionString.Split(' ')[-1]
								$Props.FQDD = "SPLD.$($i.Location -replace '\s', '')"
							}
							default {
								$Props.ElementName = $i.Name
								$Props.Location = $i.Location
								$Props.VersionString = $i.VersionString
								$Props.FQDD = "Unknown.$($i.Location -replace '\s', '')"
							}
						}
					}
					$Object = New-Object -TypeName System.Management.Automation.PSObject -Property $Props
					$Object.PSObject.TypeNames.Insert(0,'Hardware.Firmware')
					$Object
				}
			}
			Write-Verbose -Message "Disconnecting from iLo"
			Disconnect-HPREST -Session $Session
		} catch {
			Disconnect-HPREST -Session $Session
			throw
		}
	}
	END {
		Write-Verbose -Message "Cleaning up variables created by cmdlet"
		((Compare-Object -ReferenceObject (Get-Variable).Name -DifferenceObject $DefaultVariables).InputObject) | ForEach-Object -Process {
			Remove-Variable -Name $_ -Force -ErrorAction Ignore
		}
	}
}

Here is the ps1xml:

        Hardware.Firmware
        
            Hardware.Firmware
        
        
            
                
                    Name
                
				 
                    Version
                    
            
            
                
                    
                        
                            ElementName
                        
                        
                            VersionString

Here is the sample Verbose output:
VERBOSE: Splatting parameters for Connect-HPREST
VERBOSE: Connecting to x.x.x.x
VERBOSE: Firmware Uri (/rest/v1/Systems/1/FirmwareInventory) discovered
VERBOSE: 19 components discovered
VERBOSE: PCI Device Uri (/rest/v1/Systems/1/PCIDevices) discovered
VERBOSE: 13 devices discovered

VERBOSE: Disconnecting from iLo
VERBOSE: Cleaning up variables created by cmdlet (This is the END block)
Name Version

Smart HBA H240ar 4.52
HP StorageWorks 82Q 8Gb PCI-e Dual Port FC HBA 08.02.00
HP StorageWorks 82Q 8Gb PCI-e Dual Port FC HBA 08.02.00
HP Ethernet 1Gb 4-port 331i Adapter 17.4.41
HP Ethernet 10Gb 2-port 530T Adapter 7.14.79

Any help would be greatly appreciated!

2

Sorry, you can’t post XML here. You’d need to use a Gist.

So, to be clear, the concern is that the output all shows up after all the Verbose messages, correct?

3

Correct, it shows up after the END block is ran, but only occurs on the first object being processed. I originally did not use the width headers in my ps1xml, but I decided to add them to test and that seemed to resolve the problem, but I am unsure why. As I am only displaying two properties with my custom table view I didn’t want to have to manage the width.

4

So, this is about how the formatting system works. With no custom view, PowerShell can just spew each object as they come out the pipeline, and so you get output and Verbose messages intermingled.

When you specify widths, PowerShell similarly doesn’t have to do any thinking. You’ve done it all.

However, when you have a custom format and you don’t specify widths, PowerShell has to wait until it sees every object, so that it can figure out how wide to try and make each column.

Think of it this way. Normally, the pipeline looks like this:

Get-HPFirmware | Out-Default

What you ran into looked like this:

Get-HPFirmware | Format-Table -AutoSize | Out-Default

Auto size calculation always makes Format-Table block the pipeline (much like Sort-Object, and for much the same reason). You won’t see any output until the objects end up with Out-Default. When you remove the need for FT to block the pipeline, and can stream one object at a time to Out-Default, and you see output sooner.

Another thing that might be confusing you is how PowerShell manages output. There are 6 pipelines, including Verbose and Success (which is where objects get written to by Write-Output). These stay entirely separate until they HAVE to be combined because you only have one screen upon which to spew everything. The output is still happening in your PROCESS block, but until after your END block, Format-Table still wasn’t sure it had seen everything, and so it held off sending anything to Out-Default until it got the “all done” signal from upstream. That resulted in everything being combined for on-screen display in a slightly different sequence - but your code’s execution order never changed. You just didn’t SEE the output ON YOUR SCREEN in the same way.

5

Thank you very much Don! That makes complete sense and thanks for taking the time to actually explain why it behaves the way it does. One last question, does the END block “always” run or is it skipped if a terminating error occurs in the PROCESS block?

I am trying to determine the best place for cleaning up after my function has finished processing.

6

Skipped. “Terminate” means just that.

7

Ok so is the best practice to perform any clean up in the finally block?

8

Well, if you’re trapping the exception then you get to decide what to do. You could absorb it, and your function would continue normally. Or you could throw your own exception, before which you’d do any needed cleanup. So, in the Catch block, normally; if you put it in Finally, then it “cleans up” every time, whether there was an error or not.

9

Got it! Thank you again!