Persist timing info for failed nodes (#7353)

.changes/unreleased/Fixes-20230413-133157.yaml

@@ -0,0 +1,6 @@
+kind: Fixes
+body: Persist timing info in run results for failed nodes
+time: 2023-04-13T13:31:57.938847-05:00
+custom:
+  Author: stu-k
+  Issue: "5476"

core/dbt/contracts/results.py

@@ -21,13 +21,14 @@
 from dataclasses import dataclass, field
 from datetime import datetime
 from typing import (
-    Union,
+    Any,
+    Callable,
     Dict,
     List,
-    Optional,
-    Any,
     NamedTuple,
+    Optional,
     Sequence,
+    Union,
 )
 
 from dbt.clients.system import write_json
@@ -56,15 +57,16 @@ def to_msg_dict(self):
 
 # This is a context manager
 class collect_timing_info:
-    def __init__(self, name: str):
+    def __init__(self, name: str, callback: Callable[[TimingInfo], None]):
         self.timing_info = TimingInfo(name=name)
+        self.callback = callback
 
     def __enter__(self):
         self.timing_info.begin()
-        return self.timing_info
 
     def __exit__(self, exc_type, exc_value, traceback):
         self.timing_info.end()
+        self.callback(self.timing_info)
         # Note: when legacy logger is removed, we can remove the following line
         with TimingProcessor(self.timing_info):
             fire_event(

core/dbt/task/base.py

@@ -318,12 +318,11 @@ def compile_and_execute(self, manifest, ctx):
                     node_info=ctx.node.node_info,
                 )
             )
-            with collect_timing_info("compile") as timing_info:
+            with collect_timing_info("compile", ctx.timing.append):
                 # if we fail here, we still have a compiled node to return
                 # this has the benefit of showing a build path for the errant
                 # model
                 ctx.node = self.compile(manifest)
-            ctx.timing.append(timing_info)
 
             # for ephemeral nodes, we only want to compile, not run
             if not ctx.node.is_ephemeral_model or self.run_ephemeral_models:
@@ -333,12 +332,10 @@ def compile_and_execute(self, manifest, ctx):
                         node_info=ctx.node.node_info,
                     )
                 )
-                with collect_timing_info("execute") as timing_info:
+                with collect_timing_info("execute", ctx.timing.append):
                     result = self.run(ctx.node, manifest)
                     ctx.node = result.node
 
-                ctx.timing.append(timing_info)
-
         return result
 
     def _handle_catchable_exception(self, e, ctx):
@@ -402,8 +399,7 @@ def safe_run(self, manifest):
                 error = exc_str
 
         if error is not None:
-            # we could include compile time for runtime errors here
-            result = self.error_result(ctx.node, error, started, [])
+            result = self.error_result(ctx.node, error, started, ctx.timing)
         elif result is not None:
             result = self.from_run_result(result, started, ctx.timing)
         else:

tests/functional/artifacts/test_run_results.py

@@ -0,0 +1,32 @@
+import pytest
+from dbt.tests.util import run_dbt
+
+good_model_sql = """
+select 1 as id
+"""
+
+bad_model_sql = """
+something bad
+"""
+
+
+class TestRunResultsTimingSuccess:
+    @pytest.fixture(scope="class")
+    def models(self):
+        return {"model.sql": good_model_sql}
+
+    def test_timing_exists(self, project):
+        results = run_dbt(["run"])
+        assert len(results.results) == 1
+        assert len(results.results[0].timing) > 0
+
+
+class TestRunResultsTimingFailure:
+    @pytest.fixture(scope="class")
+    def models(self):
+        return {"model.sql": bad_model_sql}
+
+    def test_timing_exists(self, project):
+        results = run_dbt(["run"], expect_pass=False)
+        assert len(results.results) == 1
+        assert len(results.results[0].timing) > 0