diff --git a/.changes/unreleased/Fixes-20230413-133157.yaml b/.changes/unreleased/Fixes-20230413-133157.yaml new file mode 100644 index 00000000000..7e040af5b6f --- /dev/null +++ b/.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" diff --git a/core/dbt/contracts/results.py b/core/dbt/contracts/results.py index 7c4b553ed8b..63655f972c9 100644 --- a/core/dbt/contracts/results.py +++ b/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( diff --git a/core/dbt/task/base.py b/core/dbt/task/base.py index 2e33d5769e9..a7ec1e046db 100644 --- a/core/dbt/task/base.py +++ b/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: diff --git a/tests/functional/artifacts/test_run_results.py b/tests/functional/artifacts/test_run_results.py new file mode 100644 index 00000000000..a1e1b92187f --- /dev/null +++ b/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