none
Write-Verbose is quick or Get-Member is slow? RRS feed

  • Question

  • Hello

    I have some trouble with Write-Verbose.

    When I use Write-Verbose with Get-Member. I see something like this:

    PS C:\Users\masalov\Desktop> Get-Content .\temp.ps1
    [CmdletBinding()]
    Param
    (
    )
    
    Write-Verbose "Get-Process Output"
    Get-Process | Get-Member | Select-Object -First 3
    Write-Verbose "Get-Module output"
    Get-Module | Format-Wide Name
    
    PS C:\Users\masalov\Desktop> .\temp.ps1 -Verbose
    VERBOSE: Get-Process Output
    
    VERBOSE: Get-Module output
    
       TypeName: System.Diagnostics.Process
    
    Name    MemberType    Definition                    
    ----    ----------    ----------                    
    Handles AliasProperty Handles = Handlecount         
    Name    AliasProperty Name = ProcessName            
    NPM     AliasProperty NPM = NonpagedSystemMemorySize
    
    
    
    
    ISE                                 Microsoft.PowerShell.Management     Microsoft.PowerShell.Security      
    Microsoft.PowerShell.Utility        Microsoft.WSMan.Management                                             
    
    
    

    I see two verbose output and then result of two command. This is not correct.

    When i don't use Get-Member. I see one verbose output then result of command then verbose output then result of command. This is correct.

    PS C:\Users\masalov\Desktop> Get-Content .\temp2.ps1
    [CmdletBinding()]
    Param
    (
    )
    
    Write-Verbose "Get-Process Output"
    Get-Process | Select-Object -First 3
    Write-Verbose "Get-Module output"
    Get-Module | Format-Wide Name
    
    PS C:\Users\masalov\Desktop> .\temp2.ps1 -Verbose
    VERBOSE: Get-Process Output
    
    Handles  NPM(K)    PM(K)      WS(K) VM(M)   CPU(s)     Id ProcessName                                      
    -------  ------    -----      ----- -----   ------     -- -----------                                      
         83       7     1196       3980    46     0,03   1616 armsvc                                           
        891      46    13728      38600   143     9,69   2128 CcmExec                                          
        189      16    23196       8428    89     0,11   2496 CmRcService                                      
    VERBOSE: Get-Module output
    
    
    
    
    ISE                                                   Microsoft.PowerShell.Management                      
    Microsoft.PowerShell.Security                         Microsoft.PowerShell.Utility                         
    Microsoft.WSMan.Management                                 

    What should I do to correct this?

    Thursday, December 26, 2013 7:50 AM

Answers

  • I`m not 100% sure why this is happening, but I've seen it before. It is not only about Get-Member but depending on how the output is formatted (if you pipe the get-member to format-table the problem also goes away). The least obtrusive solution is to pipe the output to Out-Host:

    #change
    Get-Process | Get-Member | Select-Object -First 3
    
    #to
    Get-Process | Get-Member | Select-Object -First 3 | Out-Host

    • Marked as answer by Andrei Masalov Thursday, December 26, 2013 2:48 PM
    Thursday, December 26, 2013 8:49 AM

All replies

  • I`m not 100% sure why this is happening, but I've seen it before. It is not only about Get-Member but depending on how the output is formatted (if you pipe the get-member to format-table the problem also goes away). The least obtrusive solution is to pipe the output to Out-Host:

    #change
    Get-Process | Get-Member | Select-Object -First 3
    
    #to
    Get-Process | Get-Member | Select-Object -First 3 | Out-Host

    • Marked as answer by Andrei Masalov Thursday, December 26, 2013 2:48 PM
    Thursday, December 26, 2013 8:49 AM
  • Thank you very much for your answer

    Because we do not know what the problem is exactly, should we always use the Out-Host when using Write-Verbose?

    Thursday, December 26, 2013 2:53 PM
  • If you switch the order of the commands it 2il work as you expect too.

    The reason is simple.  The output from Wrire-Error,Verbose and Warning are all sent on different channels.   The order that they are displayed on the console is unimportant.  They are only ordered within the channel.  The command using Get-Member completes and is sent to the default formatter for output.  This requires deserializing the large batch of objects generated by Get-Member.  Ths is completed but the output takes some time meanwhile the next line executes very quickly.  The output appears to be ut of order but it really isn't.  Starndard Write-Outpout calls are delayedto the console to prevent flicker and console swapping.  Write-Verbose is not delayed. i am told that there is a parameter somewhere that can adjust the output delay. I do not remember what it is.

    Test:

    Add anything to the end of the command an it will behave as expected because you are not using the default formatter.

    [CmdletBinding()]
    Param()
    Write-Verbose "Get-Process Output"
    Get-Process | Get-Member | Select-Object -First 3 |%{Write-Host $_ -fore green}
    Write-Verbose "Get-Module output"
    Get-Module | Format-Wide Name
    

    That is anything but this:

    Get-Process | Get-Member | Select-Object -First 3 |%{Write-Output $_ }

    I am sure if we take the delay out of the channel it will appear to arrive in order.

    Almost anything that forces the default formatter to be changed will likely change the timing.  Whether it changes it to appear to work correctly or not is anybody's guess.

    The following will also force the timing to change but the cause is not clear.

    [CmdletBinding()]
    Param()
    Write-Verbose "Get-Process Output"
    Get-Process beats64 | Get-Member | Select-Object -First 3 |%{
       Write-Output $([datetime]::Now),$_
    }
    Write-Verbose "Get-Module output"
    Get-Module | Format-Wide Name
    

    Run this under a debugger (VS or other system debugger) and look at the execution timing of the statements.  They will be in order but the IO may not.  Multithreaded systems can behave oddly.  IO using a "channel" concept or using different "handles" can interleave the output in strange ways as each output type is likely to be handled on a separate thread or from a separate queue.

    Maybe the PosH Team will blog about this some time although it should never be a problem.  Just remember that timing of console output is not guaranteed to beordered between channels and may even change between executions.


    ¯\_(ツ)_/¯

    Thursday, December 26, 2013 4:19 PM

  • The reason is simple.  The output from Wrire-Error,Verbose and Warning are all sent on different channels.   The order that they are displayed on the console is unimportant.  They are only ordered within the channel. 

    I wonder why redirecting the verbose stream (this requires v3) or piping the Get-Member output to Out-Default (which should be the default behavior anyway) changes the output to be in the correct sequence?:

    function test{
    [CmdletBinding()]
    Param()
    	Write-Verbose "Get-Process Output"
    	Get-Process | gm | select -First 3 | Out-Default
    	Write-Verbose "Get-Module output"
    	Get-Module | Format-Wide Name
    }
    test -verbose 
    
    function test{
    [CmdletBinding()]
    Param()
    	Write-Verbose "Get-Process Output" 
    	Get-Process | Get-Member -Verbose| Select-Object -First 3 
    	Write-Verbose "Get-Module output"
    	Get-Module | Format-Wide Name
    }
    test -verbose 4>&1
    
    
    
    

    Thursday, December 26, 2013 5:42 PM
  • Anything that changes the timing is apt to change the order.  Luck of the draw I suppose.


    ¯\_(ツ)_/¯

    Thursday, December 26, 2013 5:50 PM
  • If this is about timing why does piping the (non verbose) output to something additional make it appear earlier rather than later?

    • Edited by Dirk_74 Thursday, December 26, 2013 5:56 PM
    Thursday, December 26, 2013 5:55 PM
  • That is the nature of timing and it can also be because of differences in how  default formatter is acquired and how one is used when it is explicit.

    It is not as much about earlier/later as it is about thread scheduling.  It is possible that the default formatter causes a re-queuing of the output and an explicit call does not.  In all cases we are forcing a string converion in the pipeline.

    This is really all it takes:

    [CmdletBinding()]
    Param()
    Write-Verbose "Get-Process Output"
    Get-Process beats64 | Get-Member | Select-Object -First 3 |%{
       "$_"
    }
    Write-Verbose "Get-Module output"
    Get-Module | Format-Wide Name
    

    Now remove the quotes which will force an object to be passed to one more implied stage.

    Also we re not allowing the system to inspect the object. I suspect this also contributes to the added delay which makes the output appear to be out of order.

    The only important thing is that the output is in order for each channel.  It is never assumed that different output ports will be in sync without some explicit syncing method.


    ¯\_(ツ)_/¯

    Thursday, December 26, 2013 6:41 PM
  • Playing around a bit more makes me feel that a definitive answer for this cannot be guessed or assumed.  I am pretty sure it is just the difference in how the different IO threads are managed.  Only the PowerShell Team can give us an exact answer if they choose to divulge how this is done.  Not publishing information that describes a method that can change is kind counter to the whole PowerShell philosophy of consistent usage. We should not write code that assumes that these two channels are related in any way. Any release or patch could change any behavior that we code to.  Never code to anomalies in code. If it is a bug workaround we MUST know exactly what the bug is before creating a temporary patch.

    ¯\_(ツ)_/¯

    Thursday, December 26, 2013 6:59 PM