Output duration in UiHook after successful operation completion.

[handlerbot]

Output sample: data.google_compute_zones.available: Destruction complete after 46.197682ms

(For operations longer than a second, it will be truncated to the second; using the same timestamp rendering as the still-in-process updates.)

[handlerbot]

Hi, any feedback on this? Would love to get it in before 0.10 releases. :-D

[apparentlymart]

Hi @handlerbot! Thanks for working on this.

We're currently in the feature freeze period for 0.10, so this can't be included in 0.10 final but we can take a look at it for a point release after that.

I'm kinda curious as to what use-case you have in mind for this. Why is it useful to know how long each action took? The apply output is already rather "noisy" so I'd lean towards not cluttering it with even more information, but if you have a compelling use-case we can certainly consider it.

[nbering]

I'd actually be curious to see a flag where it clears some of the current noise and just shows the elapsed time. Might be nice in cases where you're running non-interactively like BuildKite does.

[handlerbot]

Hi Martin, thanks for the info and question!

The elapsed time for an operation is useful to me when you have a cloud service like AWS, where some creation and destruction operations have been observed to take anywhere from 5 to 15 minutes to complete (e.g. NAT gateways, Elasticsearch and ElastiCache and RDS instances). Being able to easily log and extract the elapsed time lets me give feedback to the AWS teams about observed provisioning and deprovisioning performance, as well as reason about what degree of parallelism I want to run Terraform with to make my plans run as quickly as possible.

It's certainly possible to extract an approximation of this information now by looking at the ultimate progress report line for each resource before the completion line, which includes the elapsed time, but that requires post-facto text processing and correlation, whereas with my PR you can just save the Terraform output and grep it for " after " and get all of the completion lines for each resource, without any more processing. :-)

[handlerbot]

Also, some thoughts on apply output being noisy, from my intervening runs of Terraform...

1. This change doesn't add new lines, it just adds two short words to an existing line, replicating a timestamp on the "every ten seconds" progress update.

2. If we want to reduce the noise from apply, a flag that eliminates the progress update lines, or lets the operator change the interval (30 seconds? 60 seconds?) would go far and be pretty easy to implement. More fruitful and helpful, but also more complicated might be aggregating the progress updates into one line and only showing the longest outstanding operation, e.g.

Still modifying N resources, longest operation is <verb> <resource name> (ID: <id>), <duration> elapsed

[handlerbot]

Any way I can help getting this looked at, now that Terraform 0.10 is released? :-)

[apparentlymart]

Thanks for this, @handlerbot.

I merged this, though I also want to be explicit that the apply output will likely get a revamp at some point to address some of the verbosity concerns and this might end up getting backed out again at that point. However, in the mean time since (as you said) this is far from the worst culprit I don't see why we can't put this here and see how useful it turns out to be.

Thanks again for working on this, and sorry for the delay in getting it merged.

[handlerbot]

@apparentlymart Thanks for the merge, much appreciated!

Here's some feedback: the communication I got in this PR leaves me with an... unpleasant feeling at the conclusion that wasn't present in my prior contributions to Terraform.

Wanting your orchestration tool to record the duration of provisioning/modification operations that have high variability that you can analyze them afterwards seems like a reasonable simple request of self-evident benefit to me, and to my fellow Terraform users that I showed this PR to. I tried to explain the value of it in here, explicitly, when asked.

The comment of "this might end up getting backed out again" suggests that the value of what I sent wasn't appreciated or understood, and leaves me with a seed of anxiety rather than a feeling of completion and closure. I don't have any specific attachment to my code, or the form of it, staying in Terraform to accomplish this goal, but I do have an attachment to the functionality staying in Terraform, in whatever form is most reasonable and useful to the most people. That's why I sent a PR with working code, rather than just dropping a request and hoping/expecting someone else would do the work.

If you want it done differently (operation -> timing written to the local directory in JSON format?) because this is truly the straw that breaks the camel's back in terms of apply output verbosity, then let's work through that in here, that's what the PR process is for. But, "we're accepting this for now, but IDK, it's really on the edge, and we might just throw it away later" leaves me thinking that I'll have to keep an eye on every Terraform release from here on in, and if it's gotten thrown away, re-engage to get it re-added, either in the apply output or another way. I'd rather work on adding new features / fixing Terraform bugs rather than dragging back to this at some unknown point in the future. :-)

I hope this was clear, and thanks for reading. (And thank you, in all seriousness, for your time and for the merge.)

[apparentlymart]

Hi @handlerbot! I'm sorry for the lack of tact in my response here.

There are many features that can be useful in Terraform, and we need to weigh each one because each has both a value and a cost. I do understand the value based on your earlier comments, and reached the conclusion that the cost was low due to it being a pretty small addition to an already very noisy set of output, as you pointed out.

The fact is that the current output has largely evolved rather than being designed. Each new thing was "just a small thing so seems harmless" but over time that grows to be a lot. UI design is as much about what you leave out as how you put things in, and so everything here needs to be weighed in the long run when we do a full UX design pass for this command, but this will not be for some time.

With all of that said, my intent here was not to suggest that the feature is not useful, or that I am not grateful for your efforts in implementing it. As you suggest, it may just be that in the long run it is de-emphasized rather than removed entirely, such as being optionally logged to a file as you mentioned. I meant specifically that it may not stay in the main UI, not that the feature would be cut altogether.

But that is for the future. For now, I'm happy that we have your code in place to get you the information you need, and I'm sure it will be useful to others too.

Again, I'm sorry for my earlier tactless response. It's been a busy day today and I didn't take the time I should've to express myself clearly. Thanks again for working on this and sorry that we took so long to merge it; I will aim to do better next time.

[ghost]

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.

If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.