[CT-649] [Feature] Prettify duration message at the end of execution

[SOVALINUX]

Is this your first time opening an issue?

• I have read the expectations for open source contributors

Describe the Feature

Hi colleagues,
Would like to suggest more human-readable logging for end of execution dbt commands
Now we log only time in seconds, but it's not very convenient to convert it in your head every time you need to understand how long it was
For example:

Finished running 15 tests, 1 hook in 410.20s.

I would suggest to write it in the following way:

Finished running 15 tests, 1 hook in 6 min 51s (410.20s).

Saving pure seconds for those cases who might be parsing the duration from logs using RegExp

Describe alternatives you've considered

No response

Who will this benefit?

Those who execute pipelines longer than few minutes

Are you interested in contributing this feature?

I think my team can do it

Anything else?

No response

[jtcohen6]

@SOVALINUX Makes sense to me! We do something similar for bytes_processed on dbt-bigquery here. The underlying data is still recorded as an integer (number of bytes, number of seconds), but then we convert the value for inclusion in the human-friendly message.

The relevant message is in a event named HookFinished:

dbt-core/core/dbt/task/run.py

Lines 394 to 405 in 0d8e061

	def print_results_line(self, results, execution_time):
	nodes = [r.node for r in results] + self.ran_hooks
	stat_line = get_counts(nodes)
	execution = ""
	if execution_time is not None:
	execution = " in {execution_time:0.2f}s".format(execution_time=execution_time)
	with TextOnly():
	fire_event(EmptyLine())
	fire_event(HookFinished(stat_line=stat_line, execution=execution))

dbt-core/core/dbt/events/types.py

Lines 1500 to 1507 in 0d8e061

	@dataclass
	class HookFinished(InfoLevel):
	stat_line: str
	execution: str
	code: str = "E040"
	def message(self) -> str:
	return f"Finished running {self.stat_line}{self.execution}."

I'm going to mark this a good first issue. It sounds like it's a change your team may be interested in contributing?

---

Tech debt: I'll be honest, this event feels far from perfect:

• HookFinished doesn't feel like the right name, versus RunResultsLine or similar. (I'm not sure if or how we could make this change in a backwards-compatible manner, though)
• I'd much rather pass in a structured dictionary of node counts, and then render the human-friendly stat_line for the event's message
• We should also be storing execution_time as a float, rather than execution as a string

Those are beyond the scope of the specific change you're proposing. For what you're after, I think it would be reasonable to:

• Format execution, as a string, with hours/minutes/seconds (1 hr 6 min 51s)
• Add execution_time (float, representing seconds) as a dataclass attribute that gets passed into HookFinished, and included in its structured (JSON) output, even if it isn't templated into the human-friendly message

[SOVALINUX]

Hi
Will take a look, thanks! It's not the first priority for my obviously, but sooner or later we can make it :)
Thanks for your inputs!