Prettify duration message at end of execution (#5364)

* Prettify duration message at end of execution

.changes/unreleased/Features-20220611-163931.yaml

@@ -0,0 +1,7 @@
+kind: Features
+body: Prettify duration message at the end of execution
+time: 2022-06-11T16:39:31.725960083+01:00
+custom:
+  Author: jared-rimmer
+  Issue: "5253"
+  PR: "5364"

core/dbt/events/types.py

@@ -1501,10 +1501,11 @@ def message(self) -> str:
 class HookFinished(InfoLevel):
     stat_line: str
     execution: str
+    execution_time: float
     code: str = "E040"
 
     def message(self) -> str:
-        return f"Finished running {self.stat_line}{self.execution}."
+        return f"Finished running {self.stat_line}{self.execution} ({self.execution_time:0.2f}s)."
 
 
 @dataclass
@@ -2620,7 +2621,7 @@ def message(self) -> str:
     DatabaseErrorRunning(hook_type="")
     EmptyLine()
     HooksRunning(num_hooks=0, hook_type="")
-    HookFinished(stat_line="", execution="")
+    HookFinished(stat_line="", execution="", execution_time=0)
     WriteCatalogFailure(num_exceptions=0)
     CatalogWritten(path="")
     CannotGenerateDocs()

core/dbt/task/run.py

@@ -398,11 +398,13 @@ def print_results_line(self, results, execution_time):
         execution = ""
 
         if execution_time is not None:
-            execution = " in {execution_time:0.2f}s".format(execution_time=execution_time)
+            execution = utils.humanize_execution_time(execution_time=execution_time)
 
         with TextOnly():
             fire_event(EmptyLine())
-        fire_event(HookFinished(stat_line=stat_line, execution=execution))
+        fire_event(
+            HookFinished(stat_line=stat_line, execution=execution, execution_time=execution_time)
+        )
 
     def _get_deferred_manifest(self) -> Optional[WritableManifest]:
         if not self.args.defer:

core/dbt/utils.py

@@ -317,6 +317,13 @@ def timestring() -> str:
     return datetime.datetime.utcnow().isoformat() + "Z"
 
 
+def humanize_execution_time(execution_time: int) -> str:
+    minutes, seconds = divmod(execution_time, 60)
+    hours, minutes = divmod(minutes, 60)
+
+    return f" in {int(hours)} hours {int(minutes)} minutes and {seconds:0.2f} seconds"
+
+
 class JSONEncoder(json.JSONEncoder):
     """A 'custom' json encoder that does normal json encoder things, but also
     handles `Decimal`s and `Undefined`s. Decimals can lose precision because

test/unit/test_events.py

@@ -313,7 +313,7 @@ def MockNode():
     DatabaseErrorRunning(hook_type=''),
     EmptyLine(),
     HooksRunning(num_hooks=0, hook_type=''),
-    HookFinished(stat_line='', execution=''),
+    HookFinished(stat_line='', execution='', execution_time=0),
     WriteCatalogFailure(num_exceptions=0),
     CatalogWritten(path=''),
     CannotGenerateDocs(),

test/unit/test_utils.py

@@ -207,3 +207,22 @@ def test_two_members_overlap(self):
         assert md['c'] == 1
         assert md['d'] == 2
         assert md['e'] == 3
+
+class TestHumanizeExecutionTime(unittest.TestCase):
+    def test_humanzing_execution_time_with_integer(self):
+
+        result = dbt.utils.humanize_execution_time(execution_time=9460)
+
+        assert result == " in 2 hours 37 minutes and 40.00 seconds"
+
+    def test_humanzing_execution_time_with_two_decimal_place_float(self):
+
+        result = dbt.utils.humanize_execution_time(execution_time=0.32)
+
+        assert result == " in 0 hours 0 minutes and 0.32 seconds"
+
+    def test_humanzing_execution_time_with_four_decimal_place_float(self):
+
+        result = dbt.utils.humanize_execution_time(execution_time=0.3254)
+
+        assert result == " in 0 hours 0 minutes and 0.33 seconds"

tests/functional/basic/test_jaffle_shop.py

@@ -1,4 +1,4 @@
-from dbt.tests.util import run_dbt, get_manifest
+from dbt.tests.util import run_dbt, get_manifest, run_dbt_and_capture
 
 
 from tests.fixtures.jaffle_shop import JaffleShopProject
@@ -14,3 +14,11 @@ def test_basic(self, project):
         assert len(results) == 5
         manifest = get_manifest(project.project_root)
         assert "model.jaffle_shop.orders" in manifest.nodes
+
+    def test_execution_time_format_is_humanized(self, project):
+        # Create the data from seeds
+        run_dbt(["seed"])
+        _, log_output = run_dbt_and_capture(["run"])
+
+        assert " in 0 hours 0 minutes and " in log_output
+        assert " seconds" in log_output