weird delay of the output of an object when follow

Question

For some reason, the object won't output until the sleep command is done.

[pscustomobject]@{message = 'hi'}; sleep 5

Here's another example. You won't see the output until the loop finishes.

foreach ($i in 1..60) { 
  if ($i -eq 1) { [pscustomobject]@{message = $i} } 
  sleep 1
}

I guess you have to output at least 2 objects to see anything? ¯\_(ツ)_/¯ After 15 seconds, you see both objects.

foreach ($i in 1..60) {
  if ($i -eq 1 -or $i -eq 15) { [pscustomobject]@{message = $i} }
  sleep 1
}

Or output enough properties (> 4) to implicitly call format-list instead of format-table. Format-table is the problem. This comes out right away.

[pscustomobject]@{a=1; b=2; c=3; d=4; e=5}; sleep 10

I wonder if a parameter to format-table could be added like -NoWait.

Known object types with format files containing column widths don't have this problem.

foreach ($i in 1..60) { 
  if ($i -eq 1) { get-process powershell } 
  sleep 1
}

Or objects that default to format-custom:

foreach ($i in 1..60) { 
  if ($i -eq 1) { get-date } 
  sleep 1
}

Answer 1

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.

Answer 2

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-date
sleep 5
get-date} | format-table


DisplayHint 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-date
sleep 5
get-date} | format-list 

DisplayHint : DateTime
Date        : 2/8/2020 12:00:00 AM
Day         : 8
DayOfWeek   : Saturday
DayOfYear   : 39
Hour        : 20
Kind        : Local
Millisecond : 408
Minute      : 37
Month       : 2
Second      : 18
Ticks       : 637167910384087860
TimeOfDay   : 20:37:18.4087860
Year        : 2020
DateTime    : Saturday, February 8, 2020 8:37:18 PM

DisplayHint : DateTime
Date        : 2/8/2020 12:00:00 AM
Day         : 8
DayOfWeek   : Saturday
DayOfYear   : 39
Hour        : 20
Kind        : Local
Millisecond : 662
Minute      : 37
Month       : 2
Second      : 23
Ticks       : 637167910436622480
TimeOfDay   : 20:37:23.6622480
Year        : 2020
DateTime    : Saturday, February 8, 2020 8:37:23 PM

Answer 3

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