weird delay of the output of an object when followed by start-sleep (or until script end)

tl;dr

• If a command's output results in automatic tabular display (implicit Format-Table), display output can situationally be delayed for up to 300 ms. (see below for why and when), which can have two unexpected effects:

  • 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 - it effectively suspends completing the 300 ms. wait.

  • A subsequent Write-Host or Out-Host call can produce output that unexpectedly comes first.

• 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).

  • 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

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, you suspend waiting for as long as you're sleeping.

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.PS> 1; Start-Sleep 5# Implicit Format-*List* formatting due to having 5+ properties.PS> [pscustomobject]@{a=1; b=2; c=3; d=4; e=5}; 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).

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

Pipe your custom object to the Out-Host cmdlet:

[pscustomobject]@{message = 'hi'} | Out-Host; sleep 5

When you use the Out-Host cmdlet, you are immediately displaying the results to the host. Without it, the object is output to the pipeline which is not returned until after the Start-Sleep cmdlet.

Output less than 5 properties, and format-table implicitly runs. Format-table will wait an indefinite amount of time for the second object, before displaying the first object. This is for object types (like pscustomobject) without an xml file that define a default table view.

# no output for 5 seconds&{get-datesleep 5get-date} | format-tableDisplayHint DateTime                               Date                 Day DayOfWeek DayOfYear Hour  Kind Millisecond Minute----------- --------                               ----                 --- --------- --------- ----  ---- ----------- ------   DateTime Saturday, February 8, 2020 10:24:48 AM 2/8/2020 12:00:00 AM   8  Saturday        39   10 Local         618     24   DateTime Saturday, February 8, 2020 10:24:53 AM 2/8/2020 12:00:00 AM   8  Saturday        39   10 Local         892     24

Compare with format-list:

& {get-datesleep 5get-date} | format-list DisplayHint : DateTimeDate        : 2/8/2020 12:00:00 AMDay         : 8DayOfWeek   : SaturdayDayOfYear   : 39Hour        : 20Kind        : LocalMillisecond : 408Minute      : 37Month       : 2Second      : 18Ticks       : 637167910384087860TimeOfDay   : 20:37:18.4087860Year        : 2020DateTime    : Saturday, February 8, 2020 8:37:18 PMDisplayHint : DateTimeDate        : 2/8/2020 12:00:00 AMDay         : 8DayOfWeek   : SaturdayDayOfYear   : 39Hour        : 20Kind        : LocalMillisecond : 662Minute      : 37Month       : 2Second      : 23Ticks       : 637167910436622480TimeOfDay   : 20:37:23.6622480Year        : 2020DateTime    : Saturday, February 8, 2020 8:37:23 PM