Test to see if there's a difference in the recorded Query ID for dbt_artifacts model executions when post-hooks use run_query vs call statement
Project setup:
# dbt_project.yml
name: my_dbt_project
profile: all
version: "1.0.0"
models:
my_dbt_project:
+materialized: table
on-run-end:
- "{{ dbt_artifacts.upload_results(results) }}"
flags:
version_check: false # dbt_artifacts 2.7.0 requires dbt version < 1.9.0 and we're using dbt >= 1.9.0
# packages.yml
packages:
- package: brooklyn-data/dbt_artifacts
version: 2.7.0-- macros/post_hook_macros.sql
{% macro use_run_query() %}
{% if execute %}
{% do run_query("select *, 'using run_query' as what from " ~ this) %}
{% endif %}
{% endmacro %}
{% macro use_call_statement() %}
{% if execute %}
{%- call statement('select_query') -%}
select *, 'using call statement' as what from {{ this }}
{%- endcall -%}
{% endif %}
{% endmacro %}
-- models/foo_use_run_query.sql
{{ config(post_hook = "{{ use_run_query() }}") }}
select 1 id
-- models/bar_use_call_statement.sql
{{ config(post_hook = "{{ use_call_statement() }}") }}
select 1 idThere's 2 macros here that effectively does the same thing - one of our models will be using the run_query way and the other will be using the call statement method instead.
(1) let's create a fresh new schema where we will be putting our tables into (not necessary but just to keep things neat and tidy):
create or replace schema db.sch;(2) Let's install the package into our dbt project:
$ dbt deps
00:43:10 Running with dbt=1.9.1
00:43:12 Updating lock file in file path: /Users/jeremy/git/dbt-basic/package-lock.yml
00:43:12 Installing brooklyn-data/dbt_artifacts
00:43:14 Installed from version 2.7.0
00:43:14 Up to date!(3) Let's follow the quickstart and build the necessary tables for dbt_artifacts
$ dbt run -s dbt_artifacts
00:45:29 Running with dbt=1.9.1
00:45:30 Registered adapter: snowflake=1.9.0
00:45:30 Unable to do partial parsing because a project config has changed
00:45:31 Found 36 models, 1 operation, 564 macros
00:45:31
00:45:31 Concurrency: 1 threads (target='sf')
00:45:31
00:45:34 1 of 34 START sql incremental model sch.exposures .............................. [RUN]
00:45:36 1 of 34 OK created sql incremental model sch.exposures ......................... [SUCCESS 1 in 2.51s]
00:45:36 2 of 34 START sql incremental model sch.invocations ............................ [RUN]
00:45:38 2 of 34 OK created sql incremental model sch.invocations ....................... [SUCCESS 1 in 2.11s]
00:45:38 3 of 34 START sql incremental model sch.model_executions ....................... [RUN]
00:45:40 3 of 34 OK created sql incremental model sch.model_executions .................. [SUCCESS 1 in 2.04s]
00:45:40 4 of 34 START sql incremental model sch.models ................................. [RUN]
00:45:42 4 of 34 OK created sql incremental model sch.models ............................ [SUCCESS 1 in 1.99s]
00:45:42 5 of 34 START sql incremental model sch.seed_executions ........................ [RUN]
00:45:44 5 of 34 OK created sql incremental model sch.seed_executions ................... [SUCCESS 1 in 1.99s]
00:45:44 6 of 34 START sql incremental model sch.seeds .................................. [RUN]
00:45:46 6 of 34 OK created sql incremental model sch.seeds ............................. [SUCCESS 1 in 2.16s]
00:45:46 7 of 34 START sql incremental model sch.snapshot_executions .................... [RUN]
00:45:49 7 of 34 OK created sql incremental model sch.snapshot_executions ............... [SUCCESS 1 in 2.38s]
00:45:49 8 of 34 START sql incremental model sch.snapshots .............................. [RUN]
00:45:51 8 of 34 OK created sql incremental model sch.snapshots ......................... [SUCCESS 1 in 1.95s]
00:45:51 9 of 34 START sql incremental model sch.sources ................................ [RUN]
00:45:53 9 of 34 OK created sql incremental model sch.sources ........................... [SUCCESS 1 in 1.97s]
00:45:53 10 of 34 START sql incremental model sch.test_executions ....................... [RUN]
00:45:55 10 of 34 OK created sql incremental model sch.test_executions .................. [SUCCESS 1 in 2.04s]
00:45:55 11 of 34 START sql incremental model sch.tests ................................. [RUN]
00:45:57 11 of 34 OK created sql incremental model sch.tests ............................ [SUCCESS 1 in 1.97s]
00:45:57 12 of 34 START sql view model sch.stg_dbt__exposures ........................... [RUN]
00:45:57 12 of 34 OK created sql view model sch.stg_dbt__exposures ...................... [SUCCESS 1 in 0.66s]
00:45:57 13 of 34 START sql view model sch.stg_dbt__invocations ......................... [RUN]
00:45:58 13 of 34 OK created sql view model sch.stg_dbt__invocations .................... [SUCCESS 1 in 0.66s]
00:45:58 14 of 34 START sql view model sch.stg_dbt__model_executions .................... [RUN]
00:45:59 14 of 34 OK created sql view model sch.stg_dbt__model_executions ............... [SUCCESS 1 in 0.74s]
00:45:59 15 of 34 START sql view model sch.stg_dbt__models .............................. [RUN]
00:45:59 15 of 34 OK created sql view model sch.stg_dbt__models ......................... [SUCCESS 1 in 0.60s]
00:45:59 16 of 34 START sql view model sch.stg_dbt__seed_executions ..................... [RUN]
00:46:00 16 of 34 OK created sql view model sch.stg_dbt__seed_executions ................ [SUCCESS 1 in 0.59s]
00:46:00 17 of 34 START sql view model sch.stg_dbt__seeds ............................... [RUN]
00:46:01 17 of 34 OK created sql view model sch.stg_dbt__seeds .......................... [SUCCESS 1 in 0.73s]
00:46:01 18 of 34 START sql view model sch.stg_dbt__snapshot_executions ................. [RUN]
00:46:02 18 of 34 OK created sql view model sch.stg_dbt__snapshot_executions ............ [SUCCESS 1 in 1.14s]
00:46:02 19 of 34 START sql view model sch.stg_dbt__snapshots ........................... [RUN]
00:46:03 19 of 34 OK created sql view model sch.stg_dbt__snapshots ...................... [SUCCESS 1 in 0.76s]
00:46:03 20 of 34 START sql view model sch.stg_dbt__sources ............................. [RUN]
00:46:03 20 of 34 OK created sql view model sch.stg_dbt__sources ........................ [SUCCESS 1 in 0.65s]
00:46:03 21 of 34 START sql view model sch.stg_dbt__test_executions ..................... [RUN]
00:46:04 21 of 34 OK created sql view model sch.stg_dbt__test_executions ................ [SUCCESS 1 in 0.75s]
00:46:04 22 of 34 START sql view model sch.stg_dbt__tests ............................... [RUN]
00:46:07 22 of 34 OK created sql view model sch.stg_dbt__tests .......................... [SUCCESS 1 in 0.67s]
00:46:07 23 of 34 START sql view model sch.dim_dbt__exposures ........................... [RUN]
00:46:07 23 of 34 OK created sql view model sch.dim_dbt__exposures ...................... [SUCCESS 1 in 0.70s]
00:46:07 24 of 34 START sql view model sch.fct_dbt__invocations ......................... [RUN]
00:46:08 24 of 34 OK created sql view model sch.fct_dbt__invocations .................... [SUCCESS 1 in 0.77s]
00:46:08 25 of 34 START sql view model sch.fct_dbt__model_executions .................... [RUN]
00:46:09 25 of 34 OK created sql view model sch.fct_dbt__model_executions ............... [SUCCESS 1 in 0.82s]
00:46:09 26 of 34 START sql view model sch.dim_dbt__current_models ...................... [RUN]
00:46:10 26 of 34 OK created sql view model sch.dim_dbt__current_models ................. [SUCCESS 1 in 0.98s]
00:46:10 27 of 34 START sql view model sch.dim_dbt__models .............................. [RUN]
00:46:10 27 of 34 OK created sql view model sch.dim_dbt__models ......................... [SUCCESS 1 in 0.65s]
00:46:10 28 of 34 START sql view model sch.fct_dbt__seed_executions ..................... [RUN]
00:46:11 28 of 34 OK created sql view model sch.fct_dbt__seed_executions ................ [SUCCESS 1 in 0.67s]
00:46:11 29 of 34 START sql view model sch.dim_dbt__seeds ............................... [RUN]
00:46:12 29 of 34 OK created sql view model sch.dim_dbt__seeds .......................... [SUCCESS 1 in 0.65s]
00:46:12 30 of 34 START sql view model sch.fct_dbt__snapshot_executions ................. [RUN]
00:46:12 30 of 34 OK created sql view model sch.fct_dbt__snapshot_executions ............ [SUCCESS 1 in 0.64s]
00:46:12 31 of 34 START sql view model sch.dim_dbt__snapshots ........................... [RUN]
00:46:13 31 of 34 OK created sql view model sch.dim_dbt__snapshots ...................... [SUCCESS 1 in 0.64s]
00:46:13 32 of 34 START sql view model sch.dim_dbt__sources ............................. [RUN]
00:46:14 32 of 34 OK created sql view model sch.dim_dbt__sources ........................ [SUCCESS 1 in 0.63s]
00:46:14 33 of 34 START sql view model sch.fct_dbt__test_executions ..................... [RUN]
00:46:15 33 of 34 OK created sql view model sch.fct_dbt__test_executions ................ [SUCCESS 1 in 0.74s]
00:46:15 34 of 34 START sql view model sch.dim_dbt__tests ............................... [RUN]
00:46:15 34 of 34 OK created sql view model sch.dim_dbt__tests .......................... [SUCCESS 1 in 0.59s]
00:46:15
00:46:15 Uploading model executions
00:46:18 Uploading seed executions
00:46:18 Uploading test executions
00:46:18 Uploading snapshot executions
00:46:18 Uploading exposures
00:46:18 Uploading seeds
00:46:18 Uploading snapshots
00:46:18 Uploading invocations
00:46:18 Uploading sources
00:46:18 Uploading tests
00:46:18 Uploading models
00:46:19 1 of 1 START hook: my_dbt_project.on-run-end.0 ................................. [RUN]
00:46:19 1 of 1 OK hook: my_dbt_project.on-run-end.0 .................................... [OK in 3.97s]
00:46:20
00:46:20 Finished running 11 incremental models, 1 project hook, 23 view models in 0 hours 0 minutes and 49.20 seconds (49.20s).
00:46:20
00:46:20 Completed successfully
00:46:20
00:46:20 Done. PASS=35 WARN=0 ERROR=0 SKIP=0 TOTAL=35At this point - a handful of tables and views now exist in our db.sch schema:
(4) Let's build our "real" project models and inspect both what the Snowflake UI reports is the Query ID of the DDL that created the model and what is recorded in the dbt_artifacts table model_executions.
$ dbt --debug run -s foo_use_run_query bar_use_call_statement
�[0m13:49:53.749815 [info ] [MainThread]: Running with dbt=1.9.1
�[0m13:49:53.750124 [debug] [MainThread]: running dbt with arguments {'printer_width': '80', 'indirect_selection': 'eager', 'log_cache_events': 'False', 'write_json': 'True', 'partial_parse': 'True', 'cache_selected_only': 'False', 'warn_error': 'None', 'version_check': 'False', 'fail_fast': 'False', 'log_path': '/Users/jeremy/git/dbt-basic/logs', 'debug': 'True', 'profiles_dir': '/Users/jeremy/.dbt', 'use_colors': 'True', 'use_experimental_parser': 'False', 'no_print': 'None', 'quiet': 'False', 'empty': 'False', 'log_format': 'default', 'introspect': 'True', 'warn_error_options': 'WarnErrorOptions(include=[], exclude=[])', 'static_parser': 'True', 'target_path': 'None', 'invocation_command': 'dbt --debug run -s foo_use_run_query bar_use_call_statement', 'send_anonymous_usage_stats': 'True'}
�[0m13:49:54.339210 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'project_id', 'label': 'e3e7b6ee-5219-4355-986c-12b0fc94a6c2', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x117a7ca50>]}
�[0m13:49:54.362780 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'adapter_info', 'label': 'e3e7b6ee-5219-4355-986c-12b0fc94a6c2', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x120b48c10>]}
�[0m13:49:54.363501 [info ] [MainThread]: Registered adapter: snowflake=1.9.0
�[0m13:49:54.428317 [debug] [MainThread]: checksum: 5e8d1596cf4eae33c11286bbb248a722d21b9f00d8a7ced8137c642517055418, vars: {}, profile: , target: , version: 1.9.1
�[0m13:49:54.498321 [debug] [MainThread]: Partial parsing enabled: 0 files deleted, 0 files added, 0 files changed.
�[0m13:49:54.498613 [debug] [MainThread]: Partial parsing enabled, no changes found, skipping parsing
�[0m13:49:54.518787 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'load_project', 'label': 'e3e7b6ee-5219-4355-986c-12b0fc94a6c2', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x117a7cad0>]}
�[0m13:49:54.561404 [debug] [MainThread]: Wrote artifact WritableManifest to /Users/jeremy/git/dbt-basic/target/manifest.json
�[0m13:49:54.562482 [debug] [MainThread]: Wrote artifact SemanticManifest to /Users/jeremy/git/dbt-basic/target/semantic_manifest.json
�[0m13:49:54.575272 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'resource_counts', 'label': 'e3e7b6ee-5219-4355-986c-12b0fc94a6c2', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x120e10650>]}
�[0m13:49:54.575579 [info ] [MainThread]: Found 36 models, 1 operation, 564 macros
�[0m13:49:54.575745 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label': 'e3e7b6ee-5219-4355-986c-12b0fc94a6c2', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x120c89910>]}
�[0m13:49:54.576679 [info ] [MainThread]:
�[0m13:49:54.576844 [info ] [MainThread]: Concurrency: 1 threads (target='sf')
�[0m13:49:54.576981 [info ] [MainThread]:
�[0m13:49:54.578849 [debug] [MainThread]: Acquiring new snowflake connection 'master'
�[0m13:49:54.588918 [debug] [ThreadPool]: Acquiring new snowflake connection 'list_db'
�[0m13:49:54.653081 [debug] [ThreadPool]: Using snowflake connection "list_db"
�[0m13:49:54.653363 [debug] [ThreadPool]: On list_db: /* {"app": "dbt", "dbt_version": "1.9.1", "profile_name": "all", "target_name": "sf", "connection_name": "list_db"} */
show terse schemas in database db
limit 10000
�[0m13:49:54.653523 [debug] [ThreadPool]: Opening a new connection, currently in state init
�[0m13:49:56.701464 [debug] [ThreadPool]: SQL status: SUCCESS 41 in 2.048 seconds
�[0m13:49:56.709658 [debug] [ThreadPool]: Re-using an available connection from the pool (formerly list_db, now list_db_sch)
�[0m13:49:56.722674 [debug] [ThreadPool]: Using snowflake connection "list_db_sch"
�[0m13:49:56.723137 [debug] [ThreadPool]: On list_db_sch: /* {"app": "dbt", "dbt_version": "1.9.1", "profile_name": "all", "target_name": "sf", "connection_name": "list_db_sch"} */
show objects in db.sch limit 10000;
�[0m13:49:57.075537 [debug] [ThreadPool]: SQL status: SUCCESS 34 in 0.352 seconds
�[0m13:49:57.084697 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label': 'e3e7b6ee-5219-4355-986c-12b0fc94a6c2', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x1219ff590>]}
�[0m13:49:57.086499 [debug] [Thread-1 (]: Began running node model.my_dbt_project.bar_use_call_statement
�[0m13:49:57.087221 [info ] [Thread-1 (]: 1 of 2 START sql table model sch.bar_use_call_statement ........................ [RUN]
�[0m13:49:57.087707 [debug] [Thread-1 (]: Re-using an available connection from the pool (formerly list_db_sch, now model.my_dbt_project.bar_use_call_statement)
�[0m13:49:57.088068 [debug] [Thread-1 (]: Began compiling node model.my_dbt_project.bar_use_call_statement
�[0m13:49:57.094227 [debug] [Thread-1 (]: Writing injected SQL for node "model.my_dbt_project.bar_use_call_statement"
�[0m13:49:57.094825 [debug] [Thread-1 (]: Began executing node model.my_dbt_project.bar_use_call_statement
�[0m13:49:57.115345 [debug] [Thread-1 (]: Writing runtime sql for node "model.my_dbt_project.bar_use_call_statement"
�[0m13:49:57.116122 [debug] [Thread-1 (]: Using snowflake connection "model.my_dbt_project.bar_use_call_statement"
�[0m13:49:57.116378 [debug] [Thread-1 (]: On model.my_dbt_project.bar_use_call_statement: /* {"app": "dbt", "dbt_version": "1.9.1", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.bar_use_call_statement"} */
create or replace transient table db.sch.bar_use_call_statement
as
(
select 1 id
);
�[0m13:49:58.146733 [debug] [Thread-1 (]: SQL status: SUCCESS 1 in 1.030 seconds
�[0m13:49:58.152508 [debug] [Thread-1 (]: Using snowflake connection "model.my_dbt_project.bar_use_call_statement"
�[0m13:49:58.153322 [debug] [Thread-1 (]: On model.my_dbt_project.bar_use_call_statement: /* {"app": "dbt", "dbt_version": "1.9.1", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.bar_use_call_statement"} */
select *, 'using call statement' as what from db.sch.bar_use_call_statement
�[0m13:49:58.533831 [debug] [Thread-1 (]: SQL status: SUCCESS 1 in 0.380 seconds
�[0m13:49:58.562354 [debug] [Thread-1 (]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'e3e7b6ee-5219-4355-986c-12b0fc94a6c2', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x120be6f50>]}
�[0m13:49:58.563065 [info ] [Thread-1 (]: 1 of 2 OK created sql table model sch.bar_use_call_statement ................... [�[32mSUCCESS 1�[0m in 1.47s]
�[0m13:49:58.563515 [debug] [Thread-1 (]: Finished running node model.my_dbt_project.bar_use_call_statement
�[0m13:49:58.563844 [debug] [Thread-1 (]: Began running node model.my_dbt_project.foo_use_run_query
�[0m13:49:58.564383 [info ] [Thread-1 (]: 2 of 2 START sql table model sch.foo_use_run_query ............................. [RUN]
�[0m13:49:58.564797 [debug] [Thread-1 (]: Re-using an available connection from the pool (formerly model.my_dbt_project.bar_use_call_statement, now model.my_dbt_project.foo_use_run_query)
�[0m13:49:58.565098 [debug] [Thread-1 (]: Began compiling node model.my_dbt_project.foo_use_run_query
�[0m13:49:58.567244 [debug] [Thread-1 (]: Writing injected SQL for node "model.my_dbt_project.foo_use_run_query"
�[0m13:49:58.567790 [debug] [Thread-1 (]: Began executing node model.my_dbt_project.foo_use_run_query
�[0m13:49:58.569679 [debug] [Thread-1 (]: Writing runtime sql for node "model.my_dbt_project.foo_use_run_query"
�[0m13:49:58.570300 [debug] [Thread-1 (]: Using snowflake connection "model.my_dbt_project.foo_use_run_query"
�[0m13:49:58.570722 [debug] [Thread-1 (]: On model.my_dbt_project.foo_use_run_query: /* {"app": "dbt", "dbt_version": "1.9.1", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.foo_use_run_query"} */
create or replace transient table db.sch.foo_use_run_query
as
(
select 1 id
);
�[0m13:49:59.555394 [debug] [Thread-1 (]: SQL status: SUCCESS 1 in 0.984 seconds
�[0m13:49:59.562029 [debug] [Thread-1 (]: Using snowflake connection "model.my_dbt_project.foo_use_run_query"
�[0m13:49:59.563131 [debug] [Thread-1 (]: On model.my_dbt_project.foo_use_run_query: /* {"app": "dbt", "dbt_version": "1.9.1", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.foo_use_run_query"} */
select *, 'using run_query' as what from db.sch.foo_use_run_query
�[0m13:49:59.945719 [debug] [Thread-1 (]: SQL status: SUCCESS 1 in 0.381 seconds
�[0m13:49:59.951847 [debug] [Thread-1 (]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'e3e7b6ee-5219-4355-986c-12b0fc94a6c2', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x127047d90>]}
�[0m13:49:59.953298 [info ] [Thread-1 (]: 2 of 2 OK created sql table model sch.foo_use_run_query ........................ [�[32mSUCCESS 1�[0m in 1.39s]
�[0m13:49:59.954413 [debug] [Thread-1 (]: Finished running node model.my_dbt_project.foo_use_run_query
�[0m13:49:59.956399 [info ] [MainThread]:
�[0m13:49:59.970672 [info ] [MainThread]: Uploading model executions
�[0m13:50:00.003630 [debug] [MainThread]: Using snowflake connection "master"
�[0m13:50:00.004044 [debug] [MainThread]: On master: /* {"app": "dbt", "dbt_version": "1.9.1", "profile_name": "all", "target_name": "sf", "connection_name": "master"} */
insert into db.sch.model_executions
(
command_invocation_id,
node_id,
run_started_at,
was_full_refresh,
thread_id,
status,
compile_started_at,
query_completed_at,
total_node_runtime,
rows_affected,
materialization,
schema,
name,
alias,
message,
adapter_response
)
select
$1,
$2,
$3,
$4,
$5,
$6,
$7,
$8,
$9,
$10,
$11,
$12,
$13,
$14,
$15,
try_parse_json($16)
from values
(
'e3e7b6ee-5219-4355-986c-12b0fc94a6c2',
'model.my_dbt_project.bar_use_call_statement',
'2025-01-10 00:49:53.736148+00:00',
'False',
'Thread-1 (worker)',
'success',
'2025-01-10 00:49:57.088317',
'2025-01-10 00:49:58.560237',
1.472804069519043,
try_cast('1' as int),
'table',
'sch',
'bar_use_call_statement',
'bar_use_call_statement',
'SUCCESS 1',
'{\"_message\": \"SUCCESS 1\", \"code\": \"SUCCESS\", \"rows_affected\": 1, \"query_id\": \"01b99b71-0907-1b48-000d-378343a4ff12\"}'
),(
'e3e7b6ee-5219-4355-986c-12b0fc94a6c2',
'model.my_dbt_project.foo_use_run_query',
'2025-01-10 00:49:53.736148+00:00',
'False',
'Thread-1 (worker)',
'success',
'2025-01-10 00:49:58.565314',
'2025-01-10 00:49:59.951303',
1.386815071105957,
try_cast('1' as int),
'table',
'sch',
'foo_use_run_query',
'foo_use_run_query',
'SUCCESS 1',
'{\"_message\": \"SUCCESS 1\", \"code\": \"SUCCESS\", \"rows_affected\": 1, \"query_id\": \"01b99b71-0907-1b1f-000d-378343a52622\"}'
)
�[0m13:50:00.004397 [debug] [MainThread]: Opening a new connection, currently in state init
�[0m13:50:01.892146 [debug] [MainThread]: SQL status: SUCCESS 2 in 1.888 seconds
<TRUNCATED>
�[0m13:50:03.727722 [debug] [MainThread]: SQL status: SUCCESS 36 in 0.907 seconds
�[0m13:50:03.729571 [debug] [MainThread]: Writing injected SQL for node "operation.my_dbt_project.my_dbt_project-on-run-end-0"
�[0m13:50:03.735286 [info ] [MainThread]: 1 of 1 START hook: my_dbt_project.on-run-end.0 ................................. [RUN]
�[0m13:50:03.735997 [info ] [MainThread]: 1 of 1 OK hook: my_dbt_project.on-run-end.0 .................................... [�[32mOK�[0m in 3.78s]
�[0m13:50:03.736632 [debug] [MainThread]: Connection 'master' was left open.
�[0m13:50:03.737093 [debug] [MainThread]: On master: Close
�[0m13:50:04.325235 [debug] [MainThread]: Connection 'model.my_dbt_project.foo_use_run_query' was left open.
�[0m13:50:04.326622 [debug] [MainThread]: On model.my_dbt_project.foo_use_run_query: Close
�[0m13:50:04.970197 [info ] [MainThread]:
�[0m13:50:04.971290 [info ] [MainThread]: Finished running 1 project hook, 2 table models in 0 hours 0 minutes and 10.39 seconds (10.39s).
�[0m13:50:04.973077 [debug] [MainThread]: Command end result
�[0m13:50:05.014340 [debug] [MainThread]: Wrote artifact WritableManifest to /Users/jeremy/git/dbt-basic/target/manifest.json
�[0m13:50:05.015455 [debug] [MainThread]: Wrote artifact SemanticManifest to /Users/jeremy/git/dbt-basic/target/semantic_manifest.json
�[0m13:50:05.019059 [debug] [MainThread]: Wrote artifact RunExecutionResult to /Users/jeremy/git/dbt-basic/target/run_results.json
�[0m13:50:05.019268 [info ] [MainThread]:
�[0m13:50:05.019509 [info ] [MainThread]: �[32mCompleted successfully�[0m
�[0m13:50:05.019684 [info ] [MainThread]:
�[0m13:50:05.019868 [info ] [MainThread]: Done. PASS=3 WARN=0 ERROR=0 SKIP=0 TOTAL=3
�[0m13:50:05.021283 [debug] [MainThread]: Resource report: {"command_name": "run", "command_success": true, "command_wall_clock_time": 11.306752, "process_in_blocks": "0", "process_kernel_time": 0.291977, "process_mem_max_rss": "208289792", "process_out_blocks": "0", "process_user_time": 1.518487}
�[0m13:50:05.021541 [debug] [MainThread]: Command `dbt run` succeeded at 13:50:05.021493 after 11.31 seconds
�[0m13:50:05.021769 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'end', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x105182950>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x105182050>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x105182a50>]}
�[0m13:50:05.021983 [debug] [MainThread]: Flushing usage events
�[0m13:50:05.861704 [debug] [MainThread]: An error was encountered while trying to flush usage eventsTruncating the debug logs cause there's a lot of noise but the important bits are that we see 4 queries (that are not related to dbt_artifacts updating):
�[0m13:49:57.087221 [info ] [Thread-1 (]: 1 of 2 START sql table model sch.bar_use_call_statement ........................ [RUN]
�[0m13:49:57.087707 [debug] [Thread-1 (]: Re-using an available connection from the pool (formerly list_db_sch, now model.my_dbt_project.bar_use_call_statement)
�[0m13:49:57.088068 [debug] [Thread-1 (]: Began compiling node model.my_dbt_project.bar_use_call_statement
�[0m13:49:57.094227 [debug] [Thread-1 (]: Writing injected SQL for node "model.my_dbt_project.bar_use_call_statement"
�[0m13:49:57.094825 [debug] [Thread-1 (]: Began executing node model.my_dbt_project.bar_use_call_statement
�[0m13:49:57.115345 [debug] [Thread-1 (]: Writing runtime sql for node "model.my_dbt_project.bar_use_call_statement"
�[0m13:49:57.116122 [debug] [Thread-1 (]: Using snowflake connection "model.my_dbt_project.bar_use_call_statement"
�[0m13:49:57.116378 [debug] [Thread-1 (]: On model.my_dbt_project.bar_use_call_statement: /* {"app": "dbt", "dbt_version": "1.9.1", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.bar_use_call_statement"} */
create or replace transient table db.sch.bar_use_call_statement
as
(
select 1 id
);
�[0m13:49:58.146733 [debug] [Thread-1 (]: SQL status: SUCCESS 1 in 1.030 seconds
�[0m13:49:58.152508 [debug] [Thread-1 (]: Using snowflake connection "model.my_dbt_project.bar_use_call_statement"
�[0m13:49:58.153322 [debug] [Thread-1 (]: On model.my_dbt_project.bar_use_call_statement: /* {"app": "dbt", "dbt_version": "1.9.1", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.bar_use_call_statement"} */
select *, 'using call statement' as what from db.sch.bar_use_call_statement
�[0m13:49:58.533831 [debug] [Thread-1 (]: SQL status: SUCCESS 1 in 0.380 seconds
�[0m13:49:58.562354 [debug] [Thread-1 (]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'e3e7b6ee-5219-4355-986c-12b0fc94a6c2', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x120be6f50>]}
�[0m13:49:58.563065 [info ] [Thread-1 (]: 1 of 2 OK created sql table model sch.bar_use_call_statement ................... [�[32mSUCCESS 1�[0m in 1.47s]
�[0m13:49:58.563515 [debug] [Thread-1 (]: Finished running node model.my_dbt_project.bar_use_call_statement
�[0m13:49:58.563844 [debug] [Thread-1 (]: Began running node model.my_dbt_project.foo_use_run_query
�[0m13:49:58.564383 [info ] [Thread-1 (]: 2 of 2 START sql table model sch.foo_use_run_query ............................. [RUN]
�[0m13:49:58.564797 [debug] [Thread-1 (]: Re-using an available connection from the pool (formerly model.my_dbt_project.bar_use_call_statement, now model.my_dbt_project.foo_use_run_query)
�[0m13:49:58.565098 [debug] [Thread-1 (]: Began compiling node model.my_dbt_project.foo_use_run_query
�[0m13:49:58.567244 [debug] [Thread-1 (]: Writing injected SQL for node "model.my_dbt_project.foo_use_run_query"
�[0m13:49:58.567790 [debug] [Thread-1 (]: Began executing node model.my_dbt_project.foo_use_run_query
�[0m13:49:58.569679 [debug] [Thread-1 (]: Writing runtime sql for node "model.my_dbt_project.foo_use_run_query"
�[0m13:49:58.570300 [debug] [Thread-1 (]: Using snowflake connection "model.my_dbt_project.foo_use_run_query"
�[0m13:49:58.570722 [debug] [Thread-1 (]: On model.my_dbt_project.foo_use_run_query: /* {"app": "dbt", "dbt_version": "1.9.1", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.foo_use_run_query"} */
create or replace transient table db.sch.foo_use_run_query
as
(
select 1 id
);
�[0m13:49:59.555394 [debug] [Thread-1 (]: SQL status: SUCCESS 1 in 0.984 seconds
�[0m13:49:59.562029 [debug] [Thread-1 (]: Using snowflake connection "model.my_dbt_project.foo_use_run_query"
�[0m13:49:59.563131 [debug] [Thread-1 (]: On model.my_dbt_project.foo_use_run_query: /* {"app": "dbt", "dbt_version": "1.9.1", "profile_name": "all", "target_name": "sf", "node_id": "model.my_dbt_project.foo_use_run_query"} */
select *, 'using run_query' as what from db.sch.foo_use_run_query
�[0m13:49:59.945719 [debug] [Thread-1 (]: SQL status: SUCCESS 1 in 0.381 seconds
�[0m13:49:59.951847 [debug] [Thread-1 (]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label': 'e3e7b6ee-5219-4355-986c-12b0fc94a6c2', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x127047d90>]}
�[0m13:49:59.953298 [info ] [Thread-1 (]: 2 of 2 OK created sql table model sch.foo_use_run_query ........................ [�[32mSUCCESS 1�[0m in 1.39s]
What are the Query ID's associated with those 4 queries as reported by the Snowflake UI?
-- The creation of model bar_use_call_statement
create or replace transient table db.sch.bar_use_call_statement
as
(
select 1 id
);
-- 01b99b71-0907-1b48-000d-378343a4ff12
-- The post hook of model bar_use_call_statement
select *, 'using call statement' as what from db.sch.bar_use_call_statement
-- 01b99b71-0907-1d6d-000d-378343a5172a
-- The creation of model foo_use_run_query
create or replace transient table db.sch.foo_use_run_query
as
(
select 1 id
);
-- 01b99b71-0907-1b1f-000d-378343a52622
-- The post hook of model foo_use_run_query
select *, 'using run_query' as what from db.sch.foo_use_run_query
-- 01b99b72-0907-1d9a-000d-378343a53016How does that tally with what the dbt_artifacts.model_executions table recorded?
We see that in dbt_artifacts.model_executions adapter_response recorded that:
- Model
foo_use_run_queryhad a query_id of01b99b71-0907-1b48-000d-378343a4ff12which tallies with the Snowflake UI above. - Model
bar_use_call_statementhad a query_id of01b99b71-0907-1b1f-000d-378343a52622which tallies with the Snowflake UI above.
Additionally, you can double check your model's query id in the run_results.json artifact...
{
"metadata": {
"dbt_schema_version": "https://schemas.getdbt.com/dbt/run-results/v6.json",
"dbt_version": "1.9.1",
"generated_at": "2025-01-10T00:50:04.971923Z",
"invocation_id": "e3e7b6ee-5219-4355-986c-12b0fc94a6c2",
"env": {}
},
"results": [
{
"status": "success",
"timing": [
{
"name": "compile",
"started_at": "2025-01-10T00:49:57.088317Z",
"completed_at": "2025-01-10T00:49:57.094745Z"
},
{
"name": "execute",
"started_at": "2025-01-10T00:49:57.095051Z",
"completed_at": "2025-01-10T00:49:58.560237Z"
}
],
"thread_id": "Thread-1 (worker)",
"execution_time": 1.472804069519043,
"adapter_response": {
"_message": "SUCCESS 1",
"code": "SUCCESS",
"rows_affected": 1,
"query_id": "01b99b71-0907-1b48-000d-378343a4ff12"
},
"message": "SUCCESS 1",
"failures": null,
"unique_id": "model.my_dbt_project.bar_use_call_statement",
"compiled": true,
"compiled_code": "\nselect 1 id",
"relation_name": "db.sch.bar_use_call_statement",
"batch_results": null
},
{
"status": "success",
"timing": [
{
"name": "compile",
"started_at": "2025-01-10T00:49:58.565314Z",
"completed_at": "2025-01-10T00:49:58.567722Z"
},
{
"name": "execute",
"started_at": "2025-01-10T00:49:58.567996Z",
"completed_at": "2025-01-10T00:49:59.951303Z"
}
],
"thread_id": "Thread-1 (worker)",
"execution_time": 1.386815071105957,
"adapter_response": {
"_message": "SUCCESS 1",
"code": "SUCCESS",
"rows_affected": 1,
"query_id": "01b99b71-0907-1b1f-000d-378343a52622"
},
"message": "SUCCESS 1",
"failures": null,
"unique_id": "model.my_dbt_project.foo_use_run_query",
"compiled": true,
"compiled_code": "\n\nselect 1 id",
"relation_name": "db.sch.foo_use_run_query",
"batch_results": null
},
{
"status": "success",
"timing": [
{
"name": "compile",
"started_at": "2025-01-10T00:49:59.956990Z",
"completed_at": "2025-01-10T00:50:03.735076Z"
},
{
"name": "execute",
"started_at": "2025-01-10T00:50:03.735795Z",
"completed_at": "2025-01-10T00:50:03.735802Z"
}
],
"thread_id": "main",
"execution_time": 3.778812,
"adapter_response": {},
"message": "my_dbt_project.on-run-end.0 passed",
"failures": 0,
"unique_id": "operation.my_dbt_project.my_dbt_project-on-run-end-0",
"compiled": true,
"compiled_code": "\n\n \n \n \n \n \n\n \n \n\n \n\n \n \n\n \n \n \n \n\n \n \n \n\n \n \n\n \n\n \n \n\n \n \n\n \n\n \n \n\n \n \n \n \n\n \n \n\n \n \n\n \n\n \n \n\n \n \n \n \n\n \n \n\n \n \n\n \n\n \n \n\n \n \n \n \n\n \n \n\n \n \n\n \n\n \n \n\n \n \n \n \n\n \n \n\n \n \n\n \n\n \n \n\n \n \n \n \n\n \n \n\n \n \n\n \n\n \n \n\n \n \n \n \n\n \n \n\n \n \n\n \n\n \n \n\n \n \n \n \n\n \n \n \n\n \n \n\n \n\n \n \n\n \n \n\n \n\n \n \n\n \n \n \n \n\n \n \n\n \n \n\n \n\n \n \n\n \n \n \n \n\n \n \n\n \n \n\n \n\n \n \n\n \n \n \n \n\n \n \n \n\n \n \n\n \n\n \n \n\n \n \n\n ",
"relation_name": null,
"batch_results": null
}
],
"elapsed_time": 10.391587972640991,
"args": {
"version_check": false,
"introspect": true,
"skip_nodes_if_on_run_start_fails": false,
"require_resource_names_without_spaces": false,
"partial_parse": true,
"require_explicit_package_overrides_for_builtin_materializations": true,
"log_path": "/Users/jeremy/git/dbt-basic/logs",
"project_dir": "/Users/jeremy/git/dbt-basic",
"use_colors": true,
"macro_debugging": false,
"invocation_command": "dbt --debug run -s foo_use_run_query bar_use_call_statement",
"defer": false,
"vars": {},
"log_format": "default",
"write_json": true,
"empty": false,
"indirect_selection": "eager",
"cache_selected_only": false,
"log_file_max_bytes": 10485760,
"require_yaml_configuration_for_mf_time_spines": false,
"quiet": false,
"show_resource_report": false,
"log_level": "info",
"require_batched_execution_for_custom_microbatch_strategy": false,
"profiles_dir": "/Users/jeremy/.dbt",
"warn_error_options": {
"include": [],
"exclude": []
},
"log_format_file": "debug",
"partial_parse_file_diff": true,
"print": true,
"debug": true,
"printer_width": 80,
"which": "run",
"exclude": [],
"state_modified_compare_more_unrendered_values": false,
"populate_cache": true,
"require_nested_cumulative_type_params": false,
"use_colors_file": true,
"favor_state": false,
"state_modified_compare_vars": false,
"source_freshness_run_project_hooks": false,
"strict_mode": false,
"send_anonymous_usage_stats": true,
"log_level_file": "debug",
"static_parser": true,
"select": [
"foo_use_run_query",
"bar_use_call_statement"
]
}
}