[CT-846] Detailed timing info not collected for models with error status

[jtcohen6]

The timing array in run_results.json makes it possible to see the exact timestamps when a model started/finished compiling and executing. The array appears to be entirely empty if the resource encounters a runtime error.

What users see in run_results.json, for an error model vs. a success model:

"results": [
    {
      "status": "error",
      "timing": [],
      "thread_id": "Thread-1",
      "execution_time": 0.1041419506072998,
      "adapter_response": {},
      "message": "Database Error in model failing_model (models/failing_model.sql)\n  column \"abcdef\" does not exist\n  LINE 4:     select abcdef\n                     ^\n  compiled SQL at target/run/testy/models/failing_model.sql",
      "failures": null,
      "unique_id": "model.testy.failing_model"
    },
    {
      "status": "success",
      "timing": [
        {
          "name": "compile",
          "started_at": "2022-07-15T10:01:00.404848Z",
          "completed_at": "2022-07-15T10:01:00.410078Z"
        },
        {
          "name": "execute",
          "started_at": "2022-07-15T10:01:00.436724Z",
          "completed_at": "2022-07-15T10:01:00.530546Z"
        }
      ],
      "thread_id": "Thread-2",
      "execution_time": 0.12770366668701172,
      "adapter_response": {
        "_message": "CREATE VIEW",
        "code": "CREATE VIEW",
        "rows_affected": -1
      },
      "message": "CREATE VIEW",
      "failures": null,
      "unique_id": "model.testy.success_model"
    }
  ],

The relevant code is here, in the compile_and_execute method:

dbt-core/core/dbt/task/base.py

Lines 336 to 340 in f988f76

	with collect_timing_info("execute") as timing_info:
	result = self.run(ctx.node, manifest)
	ctx.node = result.node
	ctx.timing.append(timing_info)

The collect_timing_info context manager updates the timing_info attribute on self. However, it never appends timing_info above if self.run encounters an error (e.g. a database error):

ipdb> result = self.run(ctx.node, manifest)
*** dbt.exceptions.DatabaseException: Database Error
  column "aposhfaosdfj" does not exist
  LINE 4:     select aposhfaosdfj
                     ^

The resolution to this bug would find a way to return/append/update the timing_info array even when the model encounters an error during its build.

[jtcohen6]

Detailed timing information (including timestamps) would be available from the structured logging interface, which is where we're investing more of our effort around dbt Core metadata going forward

[jtcohen6]

Related: dbt-labs/dbt-snowflake#82 (comment)

Even though the response object is available from failing queries, because of the way we try materialization macros and bubble up any exceptions, we don't plumb the adapter_response back up to the run result object.