How to prevent multiple threads from competing to create dbt_test__audit schema?

jono · April 5, 2023, 6:56pm

I inherited a project with a SQL Server backend that contains 364 models and 98 tests. 18 of the first 20 are built-in tests such as accepted_values and not_null. The models build successfully, but when I get to the tests I keep getting a database error:

('42S01', "[42S01] [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]There is already an object named 'dbt_test__audit' in the database. (2714) (SQLMoreResults); [42S01] [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]CREATE SCHEMA failed due to previous errors. (2759)")

I can see in dbt.log that multiple tests are trying to create the dbt_test__audit schema at the same time. Example:

Tests 1 (accepted_values_S...) and 2 (not_null_A...) start on threads 1 and 2 respectively (lines 2043 & 2044 at top of screenshot). Thread 1 begins executing accepted_values_S and opens a new connection first (line 2056) before thread 2 (line 2060), but thread 2 tries to create the dbt_test__audit schema before thread 1 (lines 2062 and 2064). Thread 2 is therefore able to successfully commit not_null_A test 2 on line 2065 and thread 1 is forced to rollback accepted_values_S test 1 on line 2066.

This is being orchestrated via a Powershell script that creates a new database at the beginning of the run using a build profile in profiles.yml, so the dbt_audit__test schema definitely doesn’t exist beforehand. I am not logging errors with the --store-failures flag, so I don’t particularly care whether the schema gets created at all.

I tried reducing the number of concurrent threads in profiles.yml from 4 to 2 (as in the example above), but that just caused the failure to happen in the first two tests instead of slightly farther downstream. I don’t want to take concurrency down to a single thread if I can avoid it.

How can I avoid this collision? Is there a configuration I’m missing somewhere? Do I need to force each test to create its own schema (e.g., dbt_test__1, dbt_test__2, etc.)?

a_slack_user · April 5, 2023, 8:18pm

Maybe tell them to hurry up with his solution?

github.com/dbt-msft/dbt-sqlserver

Add nolock

dbt-msft:master ← Elliot2718:fix-deadlocks

opened 06:13PM - 27 Jan 22 UTC

Elliot2718

+2 -2

Adds with (nolock) to list_relations_without_caching macro. Fixes deadlock issue…s when running dbt tests in issue #195. Also see Slack thread here: https://getdbt.slack.com/archives/CMRMDDQ9W/p1640064902122500 # Outstanding questions: Are we sure adding nolock is acceptable here? My understanding is that each dbt test is independent and does not use the same database objects, which should make this fine. There could be something I'm missing though.

_{Note: @Hannes originally posted this reply in Slack. It might not have transferred perfectly.}

jono · April 7, 2023, 1:54am

Interesting, thanks for sharing. I’m not sure that resolving deadlocks will solve my issue though? I’m not actually having deadlocks, just full-on CREATE SCHEMA collisions.

This comment on the related issues thread seems most pertinent:

Isn’t part of the problems with the temporary creation of tables in Test that different tests create the same temporary table? That’s how I read the get_relation part of it

github.com/dbt-msft/dbt-sqlserver

Deadlocks on target server when more than 1 dbt thread

opened 04:00AM - 23 Dec 21 UTC

deanja

bug Size: Medium feature: essential

# Expected Behaviour dbt can run many tests in parallel without causing datab…ase deadlocks. dbt can query information_schema and do DDL on separate threads without deadlocks. # Actual Behaviour Intermittent deadlocks. So far only observed on `dbt build` (with tests) and `dbt test`. ``` ('40001', '[40001] [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]Transaction (Process ID 62) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction. (1205) (SQLFetch)') ``` An example deadlock log, showing implicated queries/ddl, is pasted at the end of this issue. # Steps to reproduce ``` dbt test --threads 8 ``` or ``` dbt build--threads 8 ``` Yesterday I could reliably get it to fail with 2 threads. Today it's running fine with 8 sometimes. Oooouch! Seems slightly easier to recreate when there are some bigger relations (10M+ rows) to test. ## Configuration A set of small generic dbt tests - I have ~50 tests DAG does not affect `dbt test`. For `dbt build` I have ~4 paths through the DAG. dbt 1.0.0 SQL Server 2019 ODBC Driver 2017 # Possible causes The "what changed recently " cause is that from dbt 0.21.1 `test` creates a lot more tables, as a workaround for there being no nested CTE functionality in SQL Server. Cause in SQL Server. Not sure, but seems the engine has it's own means of ensuring integrity when querying INFORMATION_SCHEMA and making DDL changes at the same time. In DML, the query would simply get blocked (delayed) while the write completes, not cause a deadlock, except in some edge cases involving index updates. Things were fine pre 0.21.1 probably because of lower volume of operations per second - most tests are quick, and they can take advantage of parallelism. A root cause is that there's not nested CTE in SQL Server. dbt-core tests and packages like dbt-expectations increasingly use nested CTEs. # Other information Current workaround: limit dbt threads to 1. Some discussion of possible causes and solutions on [dbt slack](https://app.slack.com/client/T0VLPD22H/CMRMDDQ9W/thread/CMRMDDQ9W-1640064902.122500) Concern in back of my mind is that we could also see this error then doing `dbt run`, given a busy enough DAG. I don't know the inner workings of dbt, but if they involve querying INFORMATION_SCHEMA and making DDL changes at the same time on another thread then there is cause for concern. No symptoms so far though :) Have also been getting SQL engine errors that the name of some test tables exceed SQL Server's maximum of 128 characters. Also intermittent, and only surfaces if there was some other error in the SQL that caused the test run to fail. # Resources Extract from a deadlock log from SQL Server: ``` <deadlock> ... </executionStack> <inputbuf> select table_catalog as [database], table_name as [name], table_schema as [schema], case when table_type = 'BASE TABLE' then 'table' when table_type = 'VIEW' then 'view' else table_type end as table_type from [dw2].information_schema.tables where table_schema like 'dbt_test__audit' </inputbuf> ... <inputbuf> USE [dw2]; if object_id ('"dbt_test__audit"."source_not_null_relation_column"','U') is not null begin drop table "dbt_test__audit"."source_not_null_relation_column" end </inputbuf> </deadlock> ``` The log was found using: (credit to [credit](https://www.sqlshack.com/how-to-resolve-deadlocks-in-sql-server/) ) ``` DECLARE @xelfilepath NVARCHAR(260) SELECT @xelfilepath = dosdlc.path FROM sys.dm_os_server_diagnostics_log_configurations AS dosdlc; SELECT @xelfilepath = @xelfilepath + N'system_health_*.xel' DROP TABLE IF EXISTS #TempTable SELECT CONVERT(XML, event_data) AS EventData INTO #TempTable FROM sys.fn_xe_file_target_read_file(@xelfilepath, NULL, NULL, NULL) WHERE object_name = 'xml_deadlock_report' SELECT EventData.value('(event/@timestamp)[1]', 'datetime2(7)') AS UtcTime, CONVERT(DATETIME, SWITCHOFFSET(CONVERT(DATETIMEOFFSET, EventData.value('(event/@timestamp)[1]', 'VARCHAR(50)')), DATENAME(TzOffset, SYSDATETIMEOFFSET()))) AS LocalTime, EventData.query('event/data/value/deadlock') AS XmlDeadlockReport FROM #TempTable ORDER BY UtcTime DESC; ``` Run it in SSMS and you'll get nice links to the xml for each deadlock.