[CT-3565] SUPER SLOW dbt run -m model_name

[ashwintastic]

Is this a new bug in dbt-core?

• I believe this is a new bug in dbt-core
• I have searched the existing issues, and I could not find an existing issue for this bug

Current Behavior

I’m running dbt run -m model_name , which is super slow when I checked the logs dbt is checking each and every tables, views in that schema by running show extended table.

Earlier in version 1.6 it was responding faster

Expected Behavior

It should pick the model asap, but it is checking for each table, views in that schema describe table

Steps To Reproduce

dbt run -m model_name

Relevant log output

--------------------------------LOGS---------------------------------------
   
   
   ============================== 22:47:58.530684 | d8769778-6f77-45ce-8fa3-2564bbaf55fb 
   ==============================
   22:47:58.530684 [info ] [MainThread]: Running with dbt=1.7.4
   22:47:58.533295 [debug] [MainThread]: running dbt with arguments {'printer_width': '80', 'indirect_selection': 'eager',    'write_json': 'True', 'log_cache_events': 'False', 'partial_parse': 'True', 'cache_selected_only': 'False', 'warn_error': 'None',    'version_check': 'True', 'fail_fast': 'False', 'log_path': 'some_path\logs', 'debug': 'False', 'profiles_dir': 'some_path',    'use_colors': 'True', 'use_experimental_parser': 'False', 'no_print': 'None', 'quiet': 'False', 'warn_error_options':    'WarnErrorOptions(include=[], exclude=[])', 'invocation_command': "dbt run -m some_model --vars {'param1': 'xxxx',    'param2':'yyyyy', 'param3': 'xyxyxyx' }", 'log_format': 'default', 'introspect': 'True', 'target_path': 'None', 'static_parser':    'True', 'send_anonymous_usage_stats': 'True'}
   22:37:21.670827 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'project_id', 'label':    'da6d902d-ca85-448d-a17c-23c11405b822', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at    0x000001A5A639DE10>]}
   22:37:21.958659 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'adapter_info', 'label':    'da6d902d-ca85-448d-a17c-23c11405b822', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at    0x000001A5B71DD4B0>]}
   22:37:21.960659 [info ] [MainThread]: Registered adapter: databricks=1.7.3
   22:37:22.018129 [debug] [MainThread]: checksum: d3f38ad46d5643a4a6fd32ce6a88e70ccb2066f8630b1f5ec7fec51d1271723b, vars:    {'source_dataset': 'SOME_SOURCE',
   'param2': 'xxxxxxxxxxxxxxxxxxx',
   'param1': 'XYZ'}, profile: , target: , version: 1.7.4
   
   22:37:22.912043 [debug] [MainThread]: Partial parsing enabled: 0 files deleted, 0 files added, 1 files changed.
   22:37:22.918044 [debug] [MainThread]: Partial parsing: updated file: databricks://macros\SOME_SCHEMA\futuristic_columns.sql
   22:37:24.115807 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'load_project', 'label':    'da6d902d-ca85-448d-a17c-23c11405b822', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at    0x000001A5B7E640D0>]}
   22:37:24.509945 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'resource_counts', 'label':    'da6d902d-ca85-448d-a17c-23c11405b822', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at    0x000001A5B7364280>]}
   22:37:24.512072 [info ] [MainThread]: Found 110 models, 16 snapshots, 501 tests, 16 sources, 0 exposures, 0 metrics, 688 macros,    0 groups, 0 semantic models
   22:37:24.513947 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label':    'da6d902d-ca85-448d-a17c-23c11405b822', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at    0x000001A5B73642E0>]}
   22:37:24.536996 [info ] [MainThread]:
   22:37:24.539946 [debug] [MainThread]: Databricks adapter: Creating DatabricksDBTConnection. name: master, thread: (11688, 24468),    compute: 22:37:24.541971 [debug] [MainThread]: Acquiring new databricks connection 'master' 22:37:24.544117 [debug] [MainThread]:    Databricks adapter: DatabricksDBTConnection._acquire: name: master, thread: (11688, 24468), compute:, acquire_release_count: 0,    idle time: 0s
   22:37:24.545945 [debug] [MainThread]: Databricks adapter: Thread (11688, 24468) using default compute resource.
   22:37:24.549979 [debug] [ThreadPool]: Databricks adapter: Creating DatabricksDBTConnection. name: list_hive_metastore, thread: (   11688, 5936), compute: 22:37:24.551945 [debug] [ThreadPool]: Acquiring new databricks connection 'list_hive_metastore'    22:37:24.552982 [debug] [ThreadPool]: Databricks adapter: DatabricksDBTConnection._acquire: name: list_hive_metastore, thread: (   11688, 5936), compute:, acquire_release_count: 0, idle time: 0s
   22:37:24.554949 [debug] [ThreadPool]: Databricks adapter: Thread (11688, 5936) using default compute resource.
   22:37:24.555980 [debug] [ThreadPool]: Using databricks connection "list_hive_metastore"
   22:37:24.557169 [debug] [ThreadPool]: On list_hive_metastore: GetSchemas(database=hive_metastore, schema=None)
   22:37:24.558000 [debug] [ThreadPool]: Opening a new connection, currently in state init
   22:37:28.841685 [debug] [ThreadPool]: SQL status: OK in 4.28000020980835 seconds
   22:37:28.854641 [debug] [ThreadPool]: Databricks adapter: DatabricksDBTConnection._release: name: list_hive_metastore, thread: (   11688, 5936), compute: , acquire_release_count: 1, idle time: 0s 22:37:28.892143 [debug] [ThreadPool]: Databricks adapter:    Creating DatabricksDBTConnection. name: list_hive_metastore_SOME_SCHEMA, thread: (11688, 23084), compute: 
   22:37:28.895142 [debug] [ThreadPool]: Acquiring new databricks connection 'list_hive_metastore_SOME_SCHEMA'
   22:37:28.898143 [debug] [ThreadPool]: Databricks adapter: DatabricksDBTConnection._acquire: name:    list_hive_metastore_SOME_SCHEMA, thread: (11688, 23084), compute: ``, acquire_release_count: 0, idle time: 0s
   22:37:28.900141 [debug] [ThreadPool]: Databricks adapter: Thread (11688, 23084) using default compute resource.
   22:37:28.927617 [debug] [ThreadPool]: Using databricks connection "list_hive_metastore_SOME_SCHEMA"
   22:37:28.933000 [debug] [ThreadPool]: On list_hive_metastore_SOME_SCHEMA: GetTables(database=hive_metastore, schema=SOME_SCHEMA,    identifier=None)
   22:37:28.935875 [debug] [ThreadPool]: Opening a new connection, currently in state init
   
   22:37:31.564096 [debug] [ThreadPool]: SQL status: OK in 2.630000114440918 seconds
   22:37:31.719021 [debug] [ThreadPool]: Spark adapter: NotImplemented: add_begin_query
   22:37:31.722029 [debug] [ThreadPool]: Using databricks connection "list_hive_metastore_SOME_SCHEMA"
   22:37:31.725030 [debug] [ThreadPool]: On list_hive_metastore_SOME_SCHEMA: /* {"app": "dbt", "dbt_version": "1.7.4",    "dbt_databricks_version": "1.7.3", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile", "target_name":    "some_env", "connection_name": "list_hive_metastore_SOME_SCHEMA"} */
   
   select current_catalog()
   22:37:32.260311 [debug] [ThreadPool]: SQL status: OK in 0.5299999713897705 seconds
   22:37:32.296242 [debug] [ThreadPool]: Using databricks connection "list_hive_metastore_SOME_SCHEMA"
   22:37:32.299069 [debug] [ThreadPool]: On list_hive_metastore_SOME_SCHEMA: /* {"app": "dbt", "dbt_version": "1.7.4",    "dbt_databricks_version": "1.7.3", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile", "target_name":    "some_env", "connection_name": "list_hive_metastore_SOME_SCHEMA"} */
   show views in hive_metastore.SOME_SCHEMA
   
   22:37:32.938768 [debug] [ThreadPool]: SQL status: OK in 0.6399999856948853 seconds
   22:37:32.980341 [debug] [ThreadPool]: Using databricks connection "list_hive_metastore_SOME_SCHEMA"
   22:37:32.983068 [debug] [ThreadPool]: On list_hive_metastore_SOME_SCHEMA: /* {"app": "dbt", "dbt_version": "1.7.4",    "dbt_databricks_version": "1.7.3", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile", "target_name":    "some_env", "connection_name": "list_hive_metastore_SOME_SCHEMA"} /
   show table extended in hive_metastore.SOME_SCHEMA like ''
   22:38:12.162673 [debug] [ThreadPool]: Databricks adapter: Reusing DatabricksDBTConnection. name:    list_hive_metastore_SOME_O_SCHEMA, thread: (11688, 23084), compute: , acquire_release_count: 0, idle time: 0.07942080497741699s    22:38:12.212333 [debug] [ThreadPool]: Databricks adapter: DatabricksDBTConnection._acquire: name:    list_hive_metastore_SOME_O_SCHEMA, thread: (11688, 23084), compute: , acquire_release_count: 0, idle time: 0.12878203392028809s
   22:38:12.256643 [debug] [ThreadPool]: Databricks adapter: Thread (11688, 23084) using default compute resource.
   22:38:12.342730 [debug] [ThreadPool]: Using databricks connection "list_hive_metastore_SOME_O_SCHEMA"
   22:38:12.369688 [debug] [ThreadPool]: On list_hive_metastore_SOME_O_SCHEMA: GetTables(database=hive_metastore,    schema=SOME_O_SCHEMA, identifier=None)
   22:38:14.369630 [debug] [ThreadPool]: SQL status: OK in 2.0 seconds
   22:38:14.532526 [debug] [ThreadPool]: Using databricks connection "list_hive_metastore_SOME_O_SCHEMA"
   22:38:14.534479 [debug] [ThreadPool]: On list_hive_metastore_SOME_O_SCHEMA: /* {"app": "dbt", "dbt_version": "1.7.4",    "dbt_databricks_version": "1.7.3", "databricks_sql_connector_version": "2.9.3", "profile_name": "data_transformation",    "target_name": "some_env", "connection_name": "list_hive_metastore_SOME_O_SCHEMA"} */
   
   select current_catalog()
   22:38:15.058400 [debug] [ThreadPool]: SQL status: OK in 0.5199999809265137 seconds
   22:38:15.072412 [debug] [ThreadPool]: Using databricks connection "list_hive_metastore_SOME_O_SCHEMA"
   22:38:15.075356 [debug] [ThreadPool]: On list_hive_metastore_SOME_O_SCHEMA: /* {"app": "dbt", "dbt_version": "1.7.4",    "dbt_databricks_version": "1.7.3", "databricks_sql_connector_version": "2.9.3", "profile_name": "data_transformation",    "target_name": "some_env", "connection_name": "list_hive_metastore_SOME_O_SCHEMA"} */
   show views in hive_metastore.SOME_O_SCHEMA
   
   22:38:15.934159 [debug] [ThreadPool]: SQL status: OK in 0.8600000143051147 seconds
   22:38:15.952715 [debug] [ThreadPool]: Using databricks connection "list_hive_metastore_SOME_O_SCHEMA"
   22:38:15.955722 [debug] [ThreadPool]: On list_hive_metastore_SOME_O_SCHEMA: /* {"app": "dbt", "dbt_version": "1.7.4",    "dbt_databricks_version": "1.7.3", "databricks_sql_connector_version": "2.9.3", "profile_name": "data_transformation",    "target_name": "some_env", "connection_name": "list_hive_metastore_SOME_O_SCHEMA"} /
   show table extended in hive_metastore.SOME_O_SCHEMA like ''

Environment

Core:
  - installed: 1.7.4
  - latest:    1.7.4 - Up to date!

Plugins:
  - databricks: 1.7.3 - Up to date!
  - spark:      1.7.1 - Up to date!
  pip 23.3.2 

Wndows 11

Python 3.10.6

Which database adapter are you using with dbt?

spark

Additional Context

No response

[ashwintastic]

It is taking 13 minutes 19 seconds to complete a single model

[dbeatty10]

Thanks for letting us know about this @ashwintastic.

Just to confirm, are you using the dbt-spark adapter, or are you using the dbt-databricks adapter?

Could you share the logs for version 1.6 versus 1.7?

Are you sure the bottleneck is metadata queries like show table extended rather than that particular incremental model taking a long time to build?

[ashwintastic]

I'm using dbt-databricks adapter logs for 1.7 is posted in the above description, logs for 1.6 is here

Are you sure the bottleneck is metadata queries like show table extended rather than that particular incremental model taking a long time to build?

Yes, model building takes only few seconds but dbt takes the model building execution after it finishes metadata queries which are bottleneck

 �[0m00:33:09.785008 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label':    'start',    'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x0000020091680730>, <      snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x00000200942DD840>, <      snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x00000200942DD600>]}
      
      
      ============================== 00:33:09.798130 | 39e7b160-208e-4429-a0e6-e6de301db17c ==============================
      �[0m00:33:09.798130 [info ] [MainThread]: Running with dbt=1.6.6
      �[0m00:33:09.798831 [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', 'fail_fast': 'False', 'debug': 'False', 'log_path': '/SOME/PATH/logs', 'profiles_dir': 'some/path',    'version_check':    'True', 'use_colors': 'True', 'use_experimental_parser': 'False', 'no_print': 'None', 'quiet': 'False',    'warn_error_options':    'WarnErrorOptions(include=[], exclude=[])', 'static_parser': 'True', 'log_format': 'default',    'invocation_command': "dbt run -m    some_table --vars {'param1': 'xxxxxxxxx', 'param2':'xxxxxxx', 'param3': 'SOME_TABLE' }",    'target_path': 'None', 'introspect':    'True', 'send_anonymous_usage_stats': 'True'}
      �[0m00:33:12.710518 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'project_id', 'label':       '39e7b160-208e-4429-a0e6-e6de301db17c', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at       0x0000020094363EE0>]}
      �[0m00:33:12.777018 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'adapter_info', 'label':       '39e7b160-208e-4429-a0e6-e6de301db17c', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at       0x00000200A51E8580>]}
      �[0m00:33:12.779020 [info ] [MainThread]: Registered adapter: databricks=1.6.6
      �[0m00:33:12.942808 [debug] [MainThread]: checksum: d8bf0f1f0820b11f4b62ede986836e74f2ab80bd13bb01f8f702478344d69ca1,    vars:    {'param1': 'SOME_TABLE',
       'param2': 'xxxxxxxxxxxxxxx',
       'param3': 'some_value'}, profile: , target: , version: 1.6.6
      �[0m00:33:13.974113 [debug] [MainThread]: Partial parsing enabled: 0 files deleted, 0 files added, 16 files changed.
      �[0m00:33:13.979126 [debug] [MainThread]: Partial parsing: updated file:       databricks://models\adhoc\some_schema\some_category\some_other_file.sql
      �[0m00:33:13.981804 [debug] [MainThread]: Partial parsing: updated file:       databricks://macros\SOME_OTHER_SCHEMA\entity_model_data_builder.sql
      �[0m00:33:13.982902 [debug] [MainThread]: Partial parsing: updated file:    databricks://macros\some_schema\some_category.sql
      �[0m00:33:13.984904 [debug] [MainThread]: Partial parsing: updated file:       databricks://models\SOME_OTHER_SCHEMA\some_category1\some_category12\some_category\some_category.sql
      �[0m00:33:13.985904 [debug] [MainThread]: Partial parsing: updated file:       databricks://models\SOME_OTHER_SCHEMA\some_category1\some_category12\some_category\stg_some_category.sql
      �[0m00:33:13.988204 [debug] [MainThread]: Partial parsing: updated file:    databricks://models\some_schema\some_category1\some      _category12\carbon_emissons_mitigation\some_category12_carbon_emission_mitigation.sql
      �[0m00:33:13.989241 [debug] [MainThread]: Partial parsing: updated file:       databricks://models\some_schema\some_category1\some_category12\some_category12\some_category_metadata.sql
      �[0m00:33:13.991688 [debug] [MainThread]: Partial parsing: updated file:       databricks://macros\to_capture\capture_data_builder.sql
      �[0m00:33:13.993281 [debug] [MainThread]: Partial parsing: updated file:       databricks://models\SOME_OTHER_SCHEMA\some_category1\some_category12\some_category12_some_category\some_table.sql
      �[0m00:33:13.994255 [debug] [MainThread]: Partial parsing: updated file:    databricks://models\adhoc\some_schema\some_category      1\some_category12\some_category12\metadata_some_category12_one_time_populate.sql
      �[0m00:33:13.996254 [debug] [MainThread]: Partial parsing: updated file:       databricks://models\some_schema\some_category1\some_category12\some_category12\some_category.sql
      �[0m00:33:13.999510 [debug] [MainThread]: Partial parsing: updated file:       databricks://macros\some_schema\update_version_end_date.sql
      �[0m00:33:14.002425 [debug] [MainThread]: Partial parsing: updated file:    databricks://models\some_schema\some_category1\some      _category12\carbon_emissons_mitigation\some_category12_carbon_emission_mitigation_metadata.sql
      �[0m00:33:14.004784 [debug] [MainThread]: Partial parsing: updated file:       databricks://models\adhoc\some_schema\some_category1\some_category12\some_category\carbon_emission_one_time_populate.sql
      �[0m00:33:14.005880 [debug] [MainThread]: Partial parsing: updated file:       databricks://models\helpers\some_other_model.sql
      �[0m00:33:14.009817 [debug] [MainThread]: Partial parsing: updated file:       databricks://models\adhoc\some_schema\some_category1\some_category12\some_category12\some_category12_one_time_populate.sql
      �[0m00:33:14.845164 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'load_project', 'label':       '39e7b160-208e-4429-a0e6-e6de301db17c', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at       0x00000200A5E08F40>]}
      �[0m00:33:15.033114 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'resource_counts', 'label':       '39e7b160-208e-4429-a0e6-e6de301db17c', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at       0x00000200A5AB54B0>]}
      �[0m00:33:15.034121 [info ] [MainThread]: Found 110 models, 16 snapshots, 501 tests, 16 sources, 0 exposures, 0    metrics,    632 macros, 0 groups, 0 semantic models
      �[0m00:33:15.035473 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label':       '39e7b160-208e-4429-a0e6-e6de301db17c', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at       0x00000200A54C7670>]}
      �[0m00:33:15.051720 [info ] [MainThread]: 
      �[0m00:33:15.054717 [debug] [MainThread]: Acquiring new databricks connection 'master'
      �[0m00:33:15.057721 [debug] [ThreadPool]: Acquiring new databricks connection 'list_schemas'
      �[0m00:33:15.068158 [debug] [ThreadPool]: Using databricks connection "list_schemas"
      �[0m00:33:15.070186 [debug] [ThreadPool]: On list_schemas: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "connection_name": "list_schemas"} */
      
          show databases
        
      �[0m00:33:15.071157 [debug] [ThreadPool]: Opening a new connection, currently in state init
      �[0m00:33:16.703666 [debug] [ThreadPool]: SQL status: OK in 1.6299999952316284 seconds
      �[0m00:33:16.711666 [debug] [ThreadPool]: On list_schemas: Close
      �[0m00:33:17.160335 [debug] [ThreadPool]: Acquiring new databricks connection 'list_None_some_schema'
      �[0m00:33:17.186341 [debug] [ThreadPool]: Spark adapter: NotImplemented: add_begin_query
      �[0m00:33:17.188402 [debug] [ThreadPool]: Using databricks connection "list_None_some_schema"
      �[0m00:33:17.189340 [debug] [ThreadPool]: On list_None_some_schema: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "connection_name": "list_None_some_schema"} */
      show tables in `some_schema`
        
      �[0m00:33:17.190336 [debug] [ThreadPool]: Opening a new connection, currently in state init
      �[0m00:33:18.919426 [debug] [ThreadPool]: SQL status: OK in 1.7300000190734863 seconds
      �[0m00:33:19.064157 [debug] [ThreadPool]: Using databricks connection "list_None_some_schema"
      �[0m00:33:19.066157 [debug] [ThreadPool]: On list_None_some_schema: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "connection_name": "list_None_some_schema"} */
      show views in `some_schema`
        
      �[0m00:33:19.873133 [debug] [ThreadPool]: SQL status: OK in 0.800000011920929 seconds
      �[0m00:33:19.931304 [debug] [ThreadPool]: On list_None_some_schema: ROLLBACK
      �[0m00:33:19.932306 [debug] [ThreadPool]: Databricks adapter: NotImplemented: rollback
      �[0m00:33:19.933578 [debug] [ThreadPool]: On list_None_some_schema: Close
      �[0m00:33:20.358773 [debug] [ThreadPool]: Re-using an available connection from the pool (formerly    list_None_some_schema,    now list_None_SOME_OTHER_SCHEMA)
      �[0m00:33:20.435722 [debug] [ThreadPool]: Spark adapter: NotImplemented: add_begin_query
      �[0m00:33:20.501249 [debug] [ThreadPool]: Using databricks connection "list_None_SOME_OTHER_SCHEMA"
      �[0m00:33:20.564461 [debug] [ThreadPool]: On list_None_SOME_OTHER_SCHEMA: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "connection_name": "list_None_SOME_OTHER_SCHEMA"} */
      show tables in `SOME_OTHER_SCHEMA`
        
      �[0m00:33:20.644338 [debug] [ThreadPool]: Opening a new connection, currently in state closed
      �[0m00:33:22.253017 [debug] [ThreadPool]: SQL status: OK in 1.6100000143051147 seconds
      �[0m00:33:22.273988 [debug] [ThreadPool]: Using databricks connection "list_None_SOME_OTHER_SCHEMA"
      �[0m00:33:22.274989 [debug] [ThreadPool]: On list_None_SOME_OTHER_SCHEMA: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "connection_name": "list_None_SOME_OTHER_SCHEMA"} */
      show views in `SOME_OTHER_SCHEMA`
        
      �[0m00:33:22.873061 [debug] [ThreadPool]: SQL status: OK in 0.6000000238418579 seconds
      �[0m00:33:22.885096 [debug] [ThreadPool]: On list_None_SOME_OTHER_SCHEMA: ROLLBACK
      �[0m00:33:22.886094 [debug] [ThreadPool]: Databricks adapter: NotImplemented: rollback
      �[0m00:33:22.886322 [debug] [ThreadPool]: On list_None_SOME_OTHER_SCHEMA: Close
      �[0m00:33:23.306430 [debug] [ThreadPool]: Re-using an available connection from the pool (formerly       list_None_SOME_OTHER_SCHEMA, now list_None_SOME_OTHER_SCHEMA)
      �[0m00:33:23.399487 [debug] [ThreadPool]: Spark adapter: NotImplemented: add_begin_query
      �[0m00:33:23.464303 [debug] [ThreadPool]: Using databricks connection "list_None_SOME_OTHER_SCHEMA"
      �[0m00:33:23.491176 [debug] [ThreadPool]: On list_None_SOME_OTHER_SCHEMA: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "connection_name": "list_None_SOME_OTHER_SCHEMA"} */
      show tables in `SOME_OTHER_SCHEMA`
        
      �[0m00:33:23.492176 [debug] [ThreadPool]: Opening a new connection, currently in state closed
      �[0m00:33:24.968321 [debug] [ThreadPool]: SQL status: OK in 1.4800000190734863 seconds
      �[0m00:33:24.984361 [debug] [ThreadPool]: Using databricks connection "list_None_SOME_OTHER_SCHEMA"
      �[0m00:33:24.985369 [debug] [ThreadPool]: On list_None_SOME_OTHER_SCHEMA: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "connection_name": "list_None_SOME_OTHER_SCHEMA"} */
      show views in `SOME_OTHER_SCHEMA`
        
      �[0m00:33:25.575944 [debug] [ThreadPool]: SQL status: OK in 0.5899999737739563 seconds
      �[0m00:33:25.588822 [debug] [ThreadPool]: On list_None_SOME_OTHER_SCHEMA: ROLLBACK
      �[0m00:33:25.589950 [debug] [ThreadPool]: Databricks adapter: NotImplemented: rollback
      �[0m00:33:25.590848 [debug] [ThreadPool]: On list_None_SOME_OTHER_SCHEMA: Close
      �[0m00:33:26.006284 [debug] [ThreadPool]: Re-using an available connection from the pool (formerly       list_None_SOME_OTHER_SCHEMA, now list_None_some_schema)
      �[0m00:33:26.066168 [debug] [ThreadPool]: Spark adapter: NotImplemented: add_begin_query
      �[0m00:33:26.099167 [debug] [ThreadPool]: Using databricks connection "list_None_some_schema"
      �[0m00:33:26.100166 [debug] [ThreadPool]: On list_None_some_schema: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "connection_name": "list_None_some_schema"} */
      show tables in `some_schema`
        
      �[0m00:33:26.100166 [debug] [ThreadPool]: Opening a new connection, currently in state closed
      �[0m00:33:27.818681 [debug] [ThreadPool]: SQL status: OK in 1.7200000286102295 seconds
      �[0m00:33:27.861758 [debug] [ThreadPool]: Using databricks connection "list_None_some_schema"
      �[0m00:33:27.863019 [debug] [ThreadPool]: On list_None_some_schema: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "connection_name": "list_None_some_schema"} */
      show views in `some_schema`
        
      �[0m00:33:28.659214 [debug] [ThreadPool]: SQL status: OK in 0.800000011920929 seconds
      �[0m00:33:28.701222 [debug] [ThreadPool]: On list_None_some_schema: ROLLBACK
      �[0m00:33:28.702165 [debug] [ThreadPool]: Databricks adapter: NotImplemented: rollback
      �[0m00:33:28.702215 [debug] [ThreadPool]: On list_None_some_schema: Close
      �[0m00:33:29.622918 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'runnable_timing', 'label':       '39e7b160-208e-4429-a0e6-e6de301db17c', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at       0x00000200A62090C0>]}
      �[0m00:33:29.624919 [debug] [MainThread]: Spark adapter: NotImplemented: add_begin_query
      �[0m00:33:29.625582 [debug] [MainThread]: Spark adapter: NotImplemented: commit
      �[0m00:33:29.626919 [info ] [MainThread]: Concurrency: 1 threads (target='dev')
      �[0m00:33:29.628261 [info ] [MainThread]: 
      �[0m00:33:29.640957 [debug] [Thread-1 (]: Began running node model.databricks.some_table
      �[0m00:33:29.642300 [info ] [Thread-1 (]: 1 of 1 START sql incremental model SOME_OTHER_SCHEMA.SOME_TABLE  [RUN]
      �[0m00:33:29.643964 [debug] [Thread-1 (]: Acquiring new databricks connection 'model.databricks.some_table'
      �[0m00:33:29.645103 [debug] [Thread-1 (]: Began compiling node model.databricks.some_table
      �[0m00:33:29.668568 [debug] [Thread-1 (]: Using databricks connection "model.databricks.some_table"
      �[0m00:33:29.669525 [debug] [Thread-1 (]: On model.databricks.some_table: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "node_id": "model.databricks.some_table"} */
      
          
          select explode(ABC) XYZT 
        from some_schema.SOME_TABLE where XYZ = SOMETABLE
        
        
      �[0m00:33:29.670566 [debug] [Thread-1 (]: Opening a new connection, currently in state init
      �[0m00:33:31.163863 [debug] [Thread-1 (]: SQL status: OK in 1.4900000095367432 seconds
      �[0m00:33:31.168310 [debug] [Thread-1 (]: Using databricks connection "model.databricks.some_table"
      �[0m00:33:31.168310 [debug] [Thread-1 (]: On model.databricks.some_table: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "node_id": "model.databricks.some_table"} */
      
          
        select explode(ABC) XYZT 
        from some_schema.SOME_TABLE where XYZ = SOMETABLE
        
        
      �[0m00:33:31.723583 [debug] [Thread-1 (]: SQL status: OK in 0.550000011920929 seconds
      �[0m00:33:31.732072 [debug] [Thread-1 (]: Writing injected SQL for node "model.databricks.some_table"
      �[0m00:33:31.735074 [debug] [Thread-1 (]: Timing info for model.databricks.some_table (compile): 00:33:29.645103 =>       00:33:31.734072
      �[0m00:33:31.736316 [debug] [Thread-1 (]: Began executing node model.databricks.some_table
      �[0m00:33:31.825662 [debug] [Thread-1 (]: Spark adapter: NotImplemented: add_begin_query
      �[0m00:33:31.827692 [debug] [Thread-1 (]: Using databricks connection "model.databricks.some_table"
      �[0m00:33:31.828731 [debug] [Thread-1 (]: On model.databricks.some_table: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "node_id": "model.databricks.some_table"} */
      
            describe extended `SOME_OTHER_SCHEMA`.`SOME_TABLE`
        
      �[0m00:33:32.564174 [debug] [Thread-1 (]: SQL status: OK in 0.7300000190734863 seconds
      �[0m00:33:32.709698 [debug] [Thread-1 (]: Using databricks connection "model.databricks.some_table"
      �[0m00:33:32.711695 [debug] [Thread-1 (]: On model.databricks.some_table: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "node_id": "model.databricks.some_table"} */
      
        
         ------------ create temporary view `some_view__dbt_tmp` as
            
      
      
          ------------------TRUNCATED LOGS-----------------------------
       
      
        ----------------- END VIEW CREATION HERE------------------------------
      
      
        
      �[0m00:33:33.734707 [debug] [Thread-1 (]: SQL status: OK in 1.0199999809265137 seconds
      �[0m00:33:33.771685 [debug] [Thread-1 (]: Using databricks connection "model.databricks.some_table"
      �[0m00:33:33.772648 [debug] [Thread-1 (]: On model.databricks.some_table: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "node_id": "model.databricks.some_table"} */
      
            describe extended `SOME_OTHER_SCHEMA`.`SOME_TABLE`
        
      �[0m00:33:34.328501 [debug] [Thread-1 (]: SQL status: OK in 0.550000011920929 seconds
      �[0m00:33:34.341889 [debug] [Thread-1 (]: Writing runtime sql for node "model.databricks.some_table"
      �[0m00:33:34.343682 [debug] [Thread-1 (]: Using databricks connection "model.databricks.some_table"
      �[0m00:33:34.343682 [debug] [Thread-1 (]: On model.databricks.some_table: /* {"app": "dbt", "dbt_version": "1.6.6",       "dbt_databricks_version": "1.6.6", "databricks_sql_connector_version": "2.9.3", "profile_name": "some_profile",    "target_name":    "dev", "node_id": "model.databricks.some_table"} */
      -- back compat for old kwarg name
        
        
        
      
        
      
        merge into XYZ as DBT_INTERNAL_DEST
            using ABC__dbt_tmp` as DBT_INTERNAL_SOURCE
            on 
                        DBT_INTERNAL_SOURCE.ID = DBT_INTERNAL_DEST.ID
                     and 
                        DBT_INTERNAL_SOURCE.T_ID = DBT_INTERNAL_DEST.T_ID
                     and 
                        DBT_INTERNAL_SOURCE.X = DBT_INTERNAL_DEST.X
                     and 
                        DBT_INTERNAL_SOURCE.OID = DBT_INTERNAL_DEST.OID
                     and 
                        DBT_INTERNAL_SOURCE.A = DBT_INTERNAL_DEST.A
                    
      
            when matched then update set
               * 
      
            when not matched then insert *
      
      �[0m00:33:40.986214 [debug] [Thread-1 (]: SQL status: OK in 6.639999866485596 seconds
      �[0m00:33:41.524258 [debug] [Thread-1 (]: Timing info for model.databricks.some_table (execute): 00:33:31.737387 =>       00:33:41.524258
      �[0m00:33:41.525681 [debug] [Thread-1 (]: On model.databricks.some_table: ROLLBACK
      �[0m00:33:41.526200 [debug] [Thread-1 (]: Databricks adapter: NotImplemented: rollback
      �[0m00:33:41.527201 [debug] [Thread-1 (]: On model.databricks.some_table: Close
      �[0m00:33:41.948229 [debug] [Thread-1 (]: Sending event: {'category': 'dbt', 'action': 'run_model', 'label':       '39e7b160-208e-4429-a0e6-e6de301db17c', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at       0x00000200A623E170>]}
      �[0m00:33:41.948747 [info ] [Thread-1 (]: 1 of 1 OK created sql incremental model SOME_OTHER_SCHEMA.SOME_TABLE        [�[32mOK�[0m in 12.31s]
      �[0m00:33:41.950711 [debug] [Thread-1 (]: Finished running node model.databricks.some_table
      �[0m00:33:41.952709 [debug] [MainThread]: On master: ROLLBACK
      �[0m00:33:41.952709 [debug] [MainThread]: Opening a new connection, currently in state init
      �[0m00:33:44.909730 [debug] [MainThread]: Databricks adapter: NotImplemented: rollback
      �[0m00:33:44.910245 [debug] [MainThread]: Spark adapter: NotImplemented: add_begin_query
      �[0m00:33:44.911300 [debug] [MainThread]: Spark adapter: NotImplemented: commit
      �[0m00:33:44.912249 [debug] [MainThread]: On master: ROLLBACK
      �[0m00:33:44.912249 [debug] [MainThread]: Databricks adapter: NotImplemented: rollback
      �[0m00:33:44.913562 [debug] [MainThread]: On master: Close
      �[0m00:33:45.332493 [debug] [MainThread]: Connection 'master' was properly closed.
      �[0m00:33:45.333494 [debug] [MainThread]: Connection 'list_schemas' was properly closed.
      �[0m00:33:45.334490 [debug] [MainThread]: Connection 'list_None_some_schema' was properly closed.
      �[0m00:33:45.335485 [debug] [MainThread]: Connection 'model.databricks.some_table' was properly closed.
      �[0m00:33:45.337486 [info ] [MainThread]: 
      �[0m00:33:45.338484 [info ] [MainThread]: Finished running 1 incremental model in 0 hours 0 minutes and 30.28 seconds    (   30.28s).
      �[0m00:33:45.339485 [debug] [MainThread]: Command end result
      �[0m00:33:45.403353 [info ] [MainThread]: 
      �[0m00:33:45.403484 [info ] [MainThread]: �[32mCompleted successfully�[0m
      �[0m00:33:45.404487 [info ] [MainThread]: 
      �[0m00:33:45.405508 [info ] [MainThread]: Done. PASS=1 WARN=0 ERROR=0 SKIP=0 TOTAL=1
      �[0m00:33:45.406521 [debug] [MainThread]: Command `dbt run` succeeded at 00:33:45.406521 after 35.67 seconds
      �[0m00:33:45.407574 [debug] [MainThread]: Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'end',       'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x0000020091680730>, <      snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x00000200A52D6AA0>, <      snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x00000200A52DC490>]}
      �[0m00:33:45.407574 [debug] [MainThread]: Flushing usage events
      �[0m00:33:46.180363 [debug] [MainThread]: Error sending anonymous usage statistics. Disabling tracking for this    execution.    If you wish to permanently disable tracking, see: https://docs.getdbt.com/reference/   global-configs#send-anonymous-usage-stats.

[dbeatty10]

Since the show extended table is in dbt-databricks here, rather than dbt-core I'm going to close this in favor of databricks/dbt-databricks#556.

[benc-db]

@dbeatty10 there is a standing issue that I've filed on this repo before (#9046), which is basically that even if the operation is only concerning 1 model, core calls list_relations_without_caching, which is what ends up triggering us to enumerate the available relations. I'm working on a fix in dbt-databricks, but fundamentally, why does get_relation require listing all of the relations in the schema?

[dbeatty10]

Thanks for linking to #9046 @benc-db !

Does #9046 (comment) answer your question? If not, could you follow-up within #9046 with whatever questions you have that are still outstanding?