Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

measure-command should be capable of streaming output either to the host or downstream cmdlets #2289

Closed
be5invis opened this issue Sep 17, 2016 · 35 comments
Labels
Issue-Discussion the issue may not have a clear classification yet. The issue may generate an RFC or may be reclassif Issue-Enhancement the issue is more of a feature request than a bug Resolution-No Activity Issue has had no activity for 6 months or more WG-Cmdlets general cmdlet issues

Comments

@be5invis
Copy link

No description provided.

@lzybkr lzybkr added the Issue-Discussion the issue may not have a clear classification yet. The issue may generate an RFC or may be reclassif label Sep 17, 2016
@lzybkr lzybkr changed the title Show the STDOUT and STDERR from the command runned by measure-command in real time. measure-command should be capable of streaming output either to the host or downstream cmdlets Sep 17, 2016
@lzybkr
Copy link
Member

lzybkr commented Sep 17, 2016

I don't think doing that by default is a good idea. Writing objects to the pipe while measuring would change how that script block performs.

You might think we could turn off the stopwatch while writing objects to downstream pipes, but downstream code that isn't measured could still have a significant impact on the code being measured.

Format and output is not always efficient. It may allocate a lot of memory. We could trigger garbage collection in ways that make measuring the performance of the script block harder.

Given this, I think it's reasonable to require Out-Host if you really want to measure the impact of formatting.

@jpsnover
Copy link
Contributor

All that is true and why we wouldn't want to change the default behavior but it seems reasonable to have a SWITCH parameter would would enable this.
I've wanted to do this myself a number of times.

@vors
Copy link
Collaborator

vors commented Sep 17, 2016

@be5invis it would be great if you can provide more details, i.e. the motivation example.

My best guess is that request is not about a downstream pipeline, but about native commands.

Measure-Command { ping ya.ru }

currently, the output of ping is collected and not passed down.

The reason I think that's the request is because the original title said STDOUT and STDERR, so I immediately think about native executables.

UPD: note that stderr is already behaves as requested, and the behavior for stdout can be achived with

Measure-Command { ping ya.ru | Write-Host }

@SteveL-MSFT SteveL-MSFT added the WG-Cmdlets general cmdlet issues label Sep 19, 2016
@ygra
Copy link

ygra commented Sep 19, 2016

So something like a -PassThru parameter? In that case it's probably beneficial to enable some way of writing the measurement results to a variable somehow, lest they are to appear with the output of the measured command (which would kinda defy the purpose).

@iSazonov
Copy link
Collaborator

iSazonov commented Nov 2, 2016

Measure-Command takes ValueFromPipeline. So the general approach is:

1,2,3,4,5 | where { largescriptblock } | foreach {...}
1,2,3,4,5 | measure-command -MeasureVariable outArray  -PipeExpression { where {largescriptblock} } | foreach {...}

@SteveL-MSFT SteveL-MSFT added Issue-Enhancement the issue is more of a feature request than a bug Up-for-Grabs Up-for-grabs issues are not high priorities, and may be opportunities for external contributors labels Nov 4, 2016
@SteveL-MSFT SteveL-MSFT added the Hacktoberfest Potential candidate to participate in Hacktoberfest label Oct 1, 2017
@SteveLasker
Copy link

A vote to including the output as a standard operation. I'd suggest we're over-focusing on the timing, and losing the context of what's being attempted. I've got a series of commands I'd like to time, because "something isn't looking right". If I don't have the output, I can't tell what's happening that might have caused a delay. While I appreciate measuring might further add to the amount of time, it's what we need to be useful. Please don't make me do some fancy stream output. Really, I just want my command to be wrapped with a start time, and end time, with the execution time. Perhaps put the timings in a green color.
measure-command {docker build} -o true -h "docker build"
-o true meaning enable the output
-h is a header that gets included in the output
The other SteveL (SteveLas-MSFT)

@dobsa
Copy link

dobsa commented Nov 30, 2018

Guys, you must be joking. Without showing the stdout and stderr while measuring, this command is largely useless. For a moment I rejoiced I finally found a way to measure a command execution time native to Windows, only to find that I cannot use it. I need to see the output of a command. I can hardly think of use cases where I would want to suppress stdout and stderr. This is just madness. Please, bring the output back to screen.

@Mike-Devel
Copy link

@dobsa: Not that I disagree, but Measure-Command { <command> | Write-Host } as suggested by @vors is imho good enough (but really needs to be documented).

@kojoru
Copy link

kojoru commented Sep 12, 2019

A better idea is | Out-Default as it will not affect unicode symbols unlike | Write-Host. And it's already in the docs apparently!

I've sent a PR to make it easier to find there: MicrosoftDocs/PowerShell-Docs#4783

@AndrewSav
Copy link

A better default is to dispaly output on screen without the need so specify | Out-Default or | Write-Host. In most of the cases you want to see the output, not to suppress it.

@pete-om
Copy link

pete-om commented Nov 20, 2019

Unfortunately, piping the output strips color :(

@felixfbecker
Copy link
Contributor

felixfbecker commented Jan 31, 2020

This is not just about interactive use cases, there's a use case for using Measure-Command in scripts too. There Out-Default won't help you because it doesn't allow to further use the pipeline output for processing. I guess you could save it in a variable but then it's not streamed anymore, which can totally skew the numbers (e.g. imagine the pipeline is limited with Select-Object -First further down).

Can we just have a -PassThru switch?

@sba923
Copy link
Contributor

sba923 commented Mar 11, 2020

I vote for a new switch that would result in getting the exact same output (color included ;-) ) as the raw command being timed.

Changing the default behavior is probably a bad idea, for backwards-compatibility's sake.

@vexx32
Copy link
Collaborator

vexx32 commented Mar 11, 2020

That's a fairly sensible suggestion. I don't see why we can't Measure-Command -PassThru

@SteveL-MSFT
Copy link
Member

Just to be clear, Measure-Command -PassThru would emit the objects that are output from the scriptblock AND write the measurements to the host?

@vexx32
Copy link
Collaborator

vexx32 commented Mar 26, 2020

Hmm. I think it'd be best if it either:

  1. Created a new object, with properties Data and Duration, or
  2. Added a new property to the output object directly (similar to Add-Member), named Duration or something along those lines.

@SeeminglyScience
Copy link
Collaborator

@vexx32 that all seems pretty complicated compared to just saving the output to a variable no?

Measure-Command { $data = Invoke-MyTest }

vs

$result = Measure-Command -PassThru { Invoke-MyTest }
$data = $result.Data
$result.Duration

@felixfbecker

I guess you could save it in a variable but then it's not streamed anymore, which can totally skew the numbers (e.g. imagine the pipeline is limited with Select-Object -First further down).

Why wouldn't the Select-Object -First be inside the Measure-Command scriptblock though? If you're trying to determine how long a code snippet takes to run, do you really want code downstream to alter it? Also as @SteveL-MSFT brought up, if you did have Select-Object -First downstream then you wouldn't get the execution length.

@iSazonov
Copy link
Collaborator

Just to be clear, Measure-Command -PassThru would emit the objects that are output from the scriptblock AND write the measurements to the host?

This is an exhaustive answer why we should not implement this request. We can always get the result with:

Measure-Command { $data = Invoke-MyTest }

@iSazonov iSazonov removed Hacktoberfest Potential candidate to participate in Hacktoberfest Up-for-Grabs Up-for-grabs issues are not high priorities, and may be opportunities for external contributors labels Mar 27, 2020
@sba923
Copy link
Contributor

sba923 commented Mar 27, 2020

"Getting the result" (pipeline data) is not the same as "getting the same results" (display).

@felixfbecker
Copy link
Contributor

This is an exhaustive answer why we should not implement this request. We can always get the result with:

Measure-Command { $data = Invoke-MyTest }

No, we can't always do that. This may be possible in most scripts, and maybe even every script you wrote personally, but it's definitely not possible in all scripts. I very recently ran a complex script that processed GB of data through the pipeline. It is simply not possible to save the pipeline output in a variable first, because it would exceed the machine's memory. That is what actually led me to this issue.

A minor downside is also that it's hard to statically analyze, e.g. VS Code will complain that $data is not used because it can't know that the script block is running in the parent's scope.

The argument that downstream consumers can slow down the pipeline is a valid one of course, and it can mean that the measured time does not represent only time spent in the script block, but also time spent by the script block waiting because of back pressure. But you don't know if that is actually going to have an impact. For example, in most cases, the "downstream consumer" will just be the host formatting + output, or maybe some light processing of the data. If what we are measuring involves IO, that time will be negligible, and as a user I would like to have the option to ignore it and tell PowerShell to just pipe it through anyway instead of requiring me to rewrite the whole script to not use pipelines (which again, may not even be possible due to memory constraints).

Ideally of course there would be a way to get the real time spent by the script block. I don't know if this is technically possible, but maybe it is, if the Measure-Command cmdlet has a steppable pipeline of the script block, maybe it could run the timer only when the script block is running, and pause it while downstream consumers are processing the emitted items. It could report both times, similar to how Unix's time reports multiple times. But even if this is not technically possible, it would still be useful to have -PassThru for the majority of the use cases.

Since I mentioned Unix's time: time forwards all output too and doesn't swallow it. This means this is also yet another thing that's surprising for people using PowerShell on platforms other than Windows.

Answering to more questions from above:

Why wouldn't the Select-Object -First be inside the Measure-Command scriptblock though? If you're trying to determine how long a code snippet takes to run, do you really want code downstream to alter it?

Yes, in some cases that's exactly what I want to do. Imagine there's a cmdlet that does REST API calls with -FollowRelLink, i.e. it will paginate potentially forever. Limiting it at some point is essential, and as a user I am aware that it would take longer if I didn't limit. I am fine with the limiting being taken into account for the execution time. I am asking to give the user the option to make that work. But also keep in mind that as said, in most cases, the "downstream consumer" will simply be light processing + host output.

Just to be clear, Measure-Command -PassThru would emit the objects that are output from the scriptblock AND write the measurements to the host?

I think that would be sensible, similar to how -IncludeTotalCount adds a TotalCount object to the output. It could be easily filtered out and redirected to e.g. the information stream in a ForEach-Object. But adding a -MeasurementVariable parameter also sounds like a good idea. There is definitely a use case for processing the measurement further as a TimeSpan object instead of writing it to the host, e.g. finding out what percentage of a total time a step took.

@SeeminglyScience
Copy link
Collaborator

Yes, in some cases that's exactly what I want to do. Imagine there's a cmdlet that does REST API calls with -FollowRelLink, i.e. it will paginate potentially forever. Limiting it at some point is essential, and as a user I am aware that it would take longer if I didn't limit. I am fine with the limiting being taken into account for the execution time. I am asking to give the user the option to make that work. But also keep in mind that as said, in most cases, the "downstream consumer" will simply be light processing + host output.

But then that's part of the test, so why wouldn't that be included in the script block? Why is it necessary to do this:

Measure-Command { Invoke-LongCommand } | Select-Object -First 1

Instead of:

Measure-Command { Invoke-LongCommand | Select-Object -First 1 }

@felixfbecker
Copy link
Contributor

You can easily do that in an example code snippet on GitHub, but that doesn't mean it's easily possible in a complex script. We could be talking about dozens of layers of function calls across multiple files, where somewhere there's the Select-Object, and somewhere you want to Measure. You can't easily restructure all the scripts and functions just to move that in there. The user should have the option to avoid that.

@SeeminglyScience
Copy link
Collaborator

You wouldn't need to restructure anything, just wrap it in a script block:

Measure-Command {
    & {
        # complicated code here
    } | Select-Object -First 1
}

Measure-Command shouldn't measure things outside of what you tell it to. If you want to change how it's measured, change the test, not the circumstances around it imo.

@iSazonov
Copy link
Collaborator

@felixfbecker Measure-Command cmdlet is not designed for scenarios you ask. The cmdlet is commonly used to measure simple script block in interactive session.
For more complex scenarios we could discuss injecting performance counters. They can provide more reliable information about script execution and more importantly for hosted applications too.

@JordanShurmer
Copy link

Just going to add my voice to the conversation,

I would also love a -PassThru flag on this command. It would indeed output the output from the script and it's own measurement output.

Since I mentioned Unix's time: time forwards all output too and doesn't swallow it. This means this is also yet another thing that's surprising for people using PowerShell on platforms other than Windows.

I was surprised it didn't already have this functionality, I guess I am more familiar with time then this command still. Also, I agree with previous remarks about the common use case requiring devs to see the output of the command they're measuring and it's far more rare that I don't care about the output (at least, in my usage of this command)

@SteveL-MSFT
Copy link
Member

If the comparison is to the time command which writes its results to stderr, then perhaps -PassThru simply writes its measurements as verbose messages? If you need to capture the measurement object for use later, then perhaps we need a -MeasurementVariable parameter?

@sba923
Copy link
Contributor

sba923 commented Mar 31, 2020

yes / yes ;-)

@AikenBM
Copy link

AikenBM commented Mar 31, 2021

I'm also going to have to agree that this is a missed feature of Measure-Command.

The problem that I run into is that I want to know how long a command is going to take including how long it takes to render output if that command is going to do that. It's important to be able to capture reality with Measure-Command.

In my mind, when I run this:

Measure-Command {
    1..10000 | ForEach-Object { [Math]::Log($_) }
}

I should get comparable time to doing this:

$s = [System.Diagnostics.Stopwatch]::StartNew()
1..10000 | ForEach-Object { [Math]::Log($_) }
$s.Stop()
$s.Elapsed.TotalMilliseconds

And I don't.

I get a difference of two orders of magnitude on my system (~60ms vs ~2800ms) because Measure-Command doesn't capture the time it takes to render output.

I shouldn't have to modify my command to make that work, either, because then I have no way to know if it's performing as it is because that's accurate or because I modified it. You can easily modify it in such a way that it greatly increases the time, after all.

For example, there's a huge difference between these because of the number of pipelines constructed:

# 1 pipeline
$a = Measure-Command {
    1..10000 | ForEach-Object { [Math]::Log($_) } | Out-Default
}

# 10,001 pipelines
$b = Measure-Command {
    1..10000 | ForEach-Object { [Math]::Log($_) | Out-Default }
}

$a.TotalMilliseconds
$b.TotalMilliseconds

The second command takes twice as long on my system (~2700ms vs ~4300ms). "Okay," you say, "so always use the first pattern." Well, if you're using a statement like foreach or for, you can't because they create empty pipelines. You can only do this:

$c = Measure-Command {
    for ($i = 1; $i -le 10000; $i++) {
        [Math]::Log($i) | Out-Default
    }
}
$c.TotalMilliseconds

That adds 10,000 pipeline constructions and teardowns to the loop. A loop that previously had no pipelines in it.

Yes, I can just use System.Diagnostics.Stopwatch. That's exactly what I do. But then I have to ask: What exactly is Measure-Command for if it's not to measure the actual time to complete?

@iSazonov
Copy link
Collaborator

@AikenBM For your scenario Measure-Script cmdlet is better choice. I hope we get it soon with #13673.

@AikenBM
Copy link

AikenBM commented Mar 31, 2021

@iSazonov That's possible. Based on a quick reading, though, that looks like it's going to be more useful for second order analysis while I'm mostly interested in first order or top level analysis?

My argument is that Measure-Command isn't as useful as it should be for even first order analysis because it hides the actual rendering or output time cost. That the command should just act like System.Diagnostics.Stopwatch timing the whole command, and not modify or capture the output.

@iSazonov
Copy link
Collaborator

@AikenBM You can download compiled artifacts from #13673, play with Measure-Script cmdlet and feedback. Currently Measure-Script cmdlet is a prototype and your (and others) feedback will be very useful.

Copy link
Contributor

This issue has not had any activity in 6 months, if this is a bug please try to reproduce on the latest version of PowerShell and reopen a new issue and reference this issue if this is still a blocker for you.

1 similar comment
Copy link
Contributor

This issue has not had any activity in 6 months, if this is a bug please try to reproduce on the latest version of PowerShell and reopen a new issue and reference this issue if this is still a blocker for you.

@microsoft-github-policy-service microsoft-github-policy-service bot added Resolution-No Activity Issue has had no activity for 6 months or more labels Nov 16, 2023
Copy link
Contributor

This issue has not had any activity in 6 months, if this is a bug please try to reproduce on the latest version of PowerShell and reopen a new issue and reference this issue if this is still a blocker for you.

Copy link
Contributor

This issue has been marked as "No Activity" as there has been no activity for 6 months. It has been closed for housekeeping purposes.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Issue-Discussion the issue may not have a clear classification yet. The issue may generate an RFC or may be reclassif Issue-Enhancement the issue is more of a feature request than a bug Resolution-No Activity Issue has had no activity for 6 months or more WG-Cmdlets general cmdlet issues
Projects
None yet
Development

No branches or pull requests