tl;dr
If a command's output is formatted with Format-Table - whether implicitly, as in your case, or explicitly - display output can situationally be delayed, for (at least) 300 milliseconds (see next section for why and when), which has the following implications:
As in the question, a subsequent Start-Sleep submitted before the delay has elapsed further delays output for (at least) the duration of the sleep.
Format-Table can only detect whether the 300-millisecond delay has elapsed if and when it regains control, which happens only when the input command either emits another output object or terminates.
With implicitly applied Format-Table formatting, a subsequent Write-Host or Out-Host call can produce output that unexpectedly comes first, as well as any call that targets an output stream other than the success output stream, e.g. a call to Write-Warning or Write-Verbose.
You can force synchronous display output by piping the command to Out-Host or to Format-Table explicitly (or any of the other Format-* cmdlets); that is, the output order across the different streams is then preserved.
- However, doing so means producing for-display output only, which means you lose the ability to (meaningfully) capture or relay the command's output.
# The Out-Host forces instant display, before sleeping starts.
# However, use of Out-Host means you can't capture the output.
[pscustomobject] @{message = 'hi'} | Out-Host; sleep 5
Background information:
The behavior is explained by the infamous PSv5+ asynchronous behavior of implicitly applied Format-Table output: For data types without predefined formatting data that have 4 or fewer properties (which is what auto-selects table display), it waits for up to 300 msecs. before displaying output, in an effort to determine suitable column widths.
If you use Start-Sleep before that period has elapsed, output is delayed for (at least) the duration of the sleep, because Format-Table doesn't regain control until it either receives the input command's next output object or the input command terminates.
Output objects that happen not to trigger implicit Format-Table formatting are not affected, however:
# Immediate output, before sleeping ends:
# Out-of-band formatting of a .NET primitive.
1; Start-Sleep 5
# Implicit Format-*List* formatting due to having 5+ properties.
[pscustomobject] @{ a=1; b=2; c=3; d=4; e=5 }; Start-Sleep 10
By contrast, because your command's output is an object with just 1 property and its type ([pscustomobject]) has no predefined formatting data associated with it, it triggers implicit Format-Table formatting and therefore exhibits the problem.
In short: The following command outputs are affected, because they select implicit Format-Table output while lacking predefined column widths, necessitating the delay:
objects whose type happens to have 4 or fewer properties
if those types have no associated predefined formatting data (see about_Format.ps1xml), which is generally true for [pscustomobject] instances.
Additionally, but far less commonly, types with formatting data that default to table view but don't have column widths predefined, are also affected (e.g., the System.Guid type instances that New-Guid outputs).
As a - cumbersome - ad-hoc alternative to authoring formatting data, you can use Format-Table with calculated properties to predefine a column width for every display property (column); however, note that this is again only suitable for to-display output; e.g.:
# Produces instant display output, due to predefined column widths.
[pscustomobject] @{ a=1; b=2 } |
Format-Table -Property @{ Expression='a'; Width = 10},
@{ Expression='b'; Width = 20}
Start-Sleep 5
Types without formatting data that have 5 or more properties default to implicitly applied Format-List, where, due to line-by-line output, there's no need to determine useful column widths, and therefore no delay.
Note that this is only a display problem, and that if the command is captured or sent to a pipeline the data is immediately output (though the command won't finish overall until the Start-Sleep period has elapsed):
# The ForEach-Object command's script block receives the [pscustomobject]
# instance right away (and itself prints it *immediately* to the display,
# due to outputting a *string* (which never triggers the asynchronous behavior).
& { [pscustomobject]@{message = 'hi'}; sleep 5 } | ForEach-Object { "[$_]" }
While there are several ways to force synchronous (immediate) display output, they all change the fundamental behavior of the command:
# Piping to Out-Host:
# Directly prints to the *display* (host).
# No way for a caller to capture the result or for processing
# the result in a pipeline.
[pscustomobject]@{message = 'hi'} | Out-Host; sleep 5
# Using Write-Host:
# Prints directly to the *display* (host) by default.
# While it *is* possible to capture the result via output stream 6.
# the information stream (6> file.txt), that output:
# * is invariably converted to *strings*
# * and the string representation does *not* use the friendly default
# output formatting; instead, the objects are stringified with simple
# [psobject.].ToString() calls, which results in a much less friendly
# representation.
Write-Host ([pscustomobject]@{message = 'hi'}); sleep 5
# Piping to a Format-* cmdlet explicitly:
# While this does write to the success-output stream (stream number 1),
# as the command would by default, what is written isn't the original
# objects, but *formatting instructions*, which are useless for further
# programmatic processing.
# However, for redirecting the output to a file with Out-File or >
# this makes no difference, because they convert the formatting instructions
# to the strings you would see on the screen by default.
# By contrast, using Set-Content or any other cmdlet that expects actual data
# would not work meaningfully.
[pscustomobject]@{message = 'hi'} | Format-Table; sleep 5
