Automatically time long-running iex commands.

[Exempll]

  This would be a neat detail. It is easy to forget to time a long-running function, and sometimes, when you are surprised by the running time, you want to know how long it ran for in retrospect. Something like `[iex] OK time=4.1s` right before the next prompt. It wouldn't need to be displayed for every command, but possibly just for the commands that pass a certain running time threshold.

[OvermindDL1]

On Tuesday, August 6, 2019 at 4:51:17 PM UTC-6, Exempll wrote:

  This would be a neat detail. It is easy to forget to time a long-running function, and sometimes, when you are surprised by the running time, you want to know how long it ran for in retrospect. Something like `[iex] OK time=4.1s` right before the next prompt. It wouldn't need to be displayed for every command, but possibly just for the commands that pass a certain running time threshold.

This would actually be pretty cool.  Could be an option to enable like colors are, but even having this by default would be very nice. 

[José Valim]

I like this idea. A PR would be welcome. What should be the default trigger? 5s?

[Fernando Tapia Rico]

I like the idea too, but I'm concerned about printing unexpected messages in the REPL, users might not know where those messages are coming from. 

As an alternative, I would like to suggest adding a new IEx helper t/0,1 that would return the execution time of the previous command or the nth command (similar to v/0,1).

[Kelvin Raffael Stinghen]

> As an alternative, I would like to suggest adding a new IEx helper t/0,1 that would return the execution time of the previous command or the nth command (similar to v/0,1).

Perfect solution IMO! It could also work with an anonymous function: `t(fn -> func3() end)`

  

Best,
Kelvin Stinghen
kelvin....@me.com

--
You received this message because you are subscribed to the Google Groups "elixir-lang-core" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elixir-lang-co...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-core/9dc355ff-e59e-48a1-84e6-75f0e0151287%40googlegroups.com.

[José Valim]

t/1 is unfortunately taken though and I believe we agreed to no longer add new single letter function to IEx. :)

One thing I really like about the automatic message is that it is discoverable. The feature is just there. And we have prior art.

--

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Director of R&D

[Dmitry Belyaev]

So the perceived problem is that developers might be confused whether the timing is emitted by the entered expression or is provided by IEx.

One way that might help with that problem is consistency. If a developer always sees the timing, even when it's practically 0us, they don't need to guess whether it's genuine output or produced by IEx.

Another way is to display the timing of the previous expression *inside* the prompt, there should be no such confusion. Some repls also allow multiline prompts, and if its easy to identify their beginnings, there should be no confusion.

We could also extend the feature to provide some other details, e.g. number of messages in the process queue (as an advice to use flush), amount of memory needed to hold the produced value, and maybe something else.

--
Kind regards,
Dmitry Belyaev

[José Valim]

Showing the time every time (and other metadata) would definitely be too verbose, even inside the prompt. But I understand the origin of the message being unclear.

[Ben Wilson]

I really like this feature idea. Often you don't know or expect that a particular function will take so long, and it's precisely at that point that you go "man, I wish I had timed that". Particularly if the function is doing a side effect, it may be non trivial to try again.

Perhaps if the messaging all happened with the `iex()` prefix it might make more sense where it's coming from?

iex(1)> some_long_fun()

iex(taking more than 5 seconds ...)

iex(returned after 15 seconds)

{:ok, :foo}

iex(2)>

[Fernando Tapia Rico]

One thing I really like about the automatic message is that it is discoverable. The feature is just there. And we have prior art.

Agreed.

And also agree with Ben Wilson on using the `iex` prefix, but I would include the number of the prompt. Here is a mockup:

If anyone wants to play a bit with it (more spaces, other message, time inside the prompt, etc), here is the mockup code: 

IO.puts("\n\niex(9)> :timer.sleep(32_000)\n" <> IO.ANSI.cyan() <> ":ok\n" <> IO.ANSI.reset() <> "iex(9) run in 32 seconds\niex(10)> _\n\n")

[José Valim]

My suggestion is to show it *before* we show the result, this way I don't think we need to include the prompt. +1 no some sort of IEx prefix:

    iex> long_operation()

    [iex] command took 12.1s

    %Some.Struct{...]

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Director of R&D

--

You received this message because you are subscribed to the Google Groups "elixir-lang-core" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elixir-lang-co...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-core/c4b48de9-7515-4555-ba61-377af0d0233e%40googlegroups.com.

[Fernando Tapia Rico]

Long-running commands could print some traces during execution and return a big list of results. If this message is printed in-between, I think it will be harder to spot.

To unsubscribe from this group and stop receiving emails from it, send an email to elixir-lang-core+unsubscribe@googlegroups.com.

[Fernando Tapia Rico]

Other alternative is to have a `time` macro that would be similar to the Unix `time` command. `time/0` would show the execution time of the last command, and `time expr` would show the execution time of the given expression.

We would loose discoverability, that's true, but we could list `time/0,1` in the IEx help (h/0); and we would gain `time expr` which would be easier to type, remember, and discover than `:timer.tc`, and could have a more human-readable output.

Thoughts?

[Ivan Ivanov]

Is it necessary to have this information on the left? This way both the result from your code and some iex internals will print there, which some people said could be confusing. What if it's on the right?

Also instead of showing the time it took to run, could iex allow some customization and the execution time could be one of the possibilities?

For example, my terminal has the datetime on the right, which allows me to measure time, too:

This is done by configuring the right prompt, which is currently not supported by iex: `RPROMPT="[%D{%f/%m/%y}|%*]"`

Doing it exactly like this won't allow measuring the time it took but it can be extended.

It can also be useful for other scenarios. An example is tracking timeouts - if you run a task/call with N seconds timeout, it's easy to see that it was started more than N seconds ago just by looking at the datetime of the command that initiated it.

[Fernando Tapia Rico]

I would like to withdraw my proposal of `time/0,1` as it might lead to developers benchmarking things in the shell. 

[Mário Guimarães]

+1 on this nice proposal.

[Exempll]

I think displaying the running time to the right of the result would be ideal.

The user will not think it is program output, since it is to the right and on the same line as the result.

     iex(14)> :timer.sleep(4000)
     :ok                                                         4.000s
     iex(15)>

It would also be great if you could see for how long the program has already been running when it has not completed yet. If it is technically possible, this could be done with updating text on the terminal. The 'result' line would be immediately visible after starting the command, with the return value replaced with three updating dots ('' '.' '..' '...'). And the running time updating live to the right.

Before program is done:

     iex(16)> :timer.sleep(4000); IO.puts("[program output]"); :timer.sleep(4000)
     [program output]
     ...                                                                                                                                             6.421s

After it is done:

     iex(16)> :timer.sleep(4000); IO.puts("[program output]"); :timer.sleep(4000)
     [program output]
     :ok                                                                                                                                           8.000s

     iex(17)>        

If live updating text is not an option I don't think intermediate values should be printed. It would not be possible to distinguish them reliably from program output.

It is always nice if it can be configured as well.

Op vrijdag 18 oktober 2019 11:51:32 UTC+2 schreef Ivan Ivanov:

[José Valim]

Let's go easy. :) Showing the timer as it does adds a bunch of complexity. Showing it on the right also means we need to integrate with the inspect algorithm to  make sure they do not overlap. All of those are added complexity. For now, we will only show a message at the end when above a threshold (configurable but defaults to 5s).

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Director of R&D

--

You received this message because you are subscribed to the Google Groups "elixir-lang-core" group.

To unsubscribe from this group and stop receiving emails from it, send an email to elixir-lang-co...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-core/de60be41-12b6-4f45-9556-e6e2c5edda5b%40googlegroups.com.

[Wojtek Mach]

+1 from me for `IEx.Helpers.time`. It doesn't solve the „oh I wish I timed this command” problem, but I think its useful on its own, and personally I'd much rather have just this.

I suggested something somewhat similiar with additional timing information in a `Kernel.dbg` macro proposal. One of the criticisms was such timing info is not representative, and in fact can be way skewed eg if the module wasn't loaded yet. Because it’s in IEx, perhaps it’s a bit clearer it’s a “one-off” measurement than a full fledged one that could be expected from Kernel module? (Perhaps it’s a false dichotomy.) And regarding time skew, at least for module loading, because we can make it a macro if we see `time Mod.fun` maybe we can try loading `Mod` before timing it? However, if Mod.fun calls Mod2.fun2 and that’s not loaded either, we would have to pay the price anyway.

[Kelvin Raffael Stinghen]

> It doesn't solve the „oh I wish I timed this command” problem, but I think its useful on its own, and personally I'd much rather have just this.

What if `IEx.Helpers.time` accepts an integer `n` as the parameter to get the time for the `n`th previously executed commandas? That would solve this problem.

About having just this though, I think I agree that showing it for slow commands automatically adds some discoverability to it. But maybe if we go with automatically showing it, we should also print out why that was shown, how to disable it (I think we should have this option) and how to show it for he other commands.

Best,
Kelvin Stinghen
Kelvin....@me.com

Sent from my iPhone