0

The title says "unrelated" because that's what they are supposed to be but apparently not...

I've got two stored procedures (log_sequence_event and log_se_event) that causes a deadlock and I've got no clue to why. They are called by the same Python app in different threads through PYODBC with autocommit off. The threads do a max of 2000 calls before committing.
sequence and se are not to be confused with each other, they are completely unrelated.

Both procedures makes an insert to their respective tables (fact.sequence and fact.se) and each table has a separate indexed view on it (v_daily_fact_sequence and v_daily_fact_se).
The procedure log_se_event does a select (with join) from the tables dim.se and dim.network (which has no connection to sequences) before the insert to fact.se. The log_sequence_event isn't doing anything before the insert.

If I understand the deadlock report correctly the deadlock happens when log_sequence_event holds a RangeS-U lock on the index for view v_daily_fact_se and log_se_event holds a RangeS-U lock on the index for view v_daily_fact_sequence and they then want a lock for the other index. This is (for me) the wtf part, why is log_sequence_event holding a lock on the index for v_daily_fact_se and vice versa?
This is on my laptop running SQL Server 2019 Developers Edition.

The parts involved:

  • The procs:
create procedure [ETL_1.7.1].log_sequence_event
(
    @terminal_id int,
    @terminal_row_id bigint,
    @timestamp datetime2(3),
    @id int,
    @event int,
    @energy int,
    @duration int,
    @weight int = null,
    @no_of_dvs int,
    @average_fill_degree int --not used
)
as
    if (@event < 100)
        insert into fact.sequence
        (
            terminal_id,
            terminal_row_id,
            [timestamp],
            sequence_id,
            event_type_id,
            pred_kwh,
            pred_dv_count,
            pred_duration,
            pred_collected_weight,
            actual_kwh,
            actual_dv_count,
            actual_duration,
            actual_collected_weight
        )
        values
        (
            @terminal_id,--terminal_id,
            @terminal_row_id,--terminal_row_id,
            @timestamp,--[timestamp],
            @id,--sequence_id,
            @event,--event_type_id,
            @energy,--pred_kwh,
            @no_of_dvs,--pred_dv_count,
            @duration,--pred_duration,
            @weight,--pred_collected_weight,
            0,--actual_kwh,
            0,--actual_dv_count,
            0,--actual_duration,
            0--actual_collected_weight
        )
    else
        insert into fact.sequence
        (
            terminal_id,
            terminal_row_id,
            [timestamp],
            sequence_id,
            event_type_id,
            pred_kwh,
            pred_dv_count,
            pred_duration,
            pred_collected_weight,
            actual_kwh,
            actual_dv_count,
            actual_duration,
            actual_collected_weight
        )
        values
        (
            @terminal_id,--terminal_id,
            @terminal_row_id,--terminal_row_id,
            @timestamp,--[timestamp],
            @id,--sequence_id,
            @event,--event_type_id,
            0,--pred_kwh,
            0,--pred_dv_count,
            0,--pred_duration,
            0,--pred_collected_weight,
            @energy,--actual_kwh,
            @no_of_dvs,--actual_dv_count,
            @duration,--actual_duration,
            @weight--actual_collected_weight
        )
go


create procedure [ETL_1.7.1].log_se_event
(
    @terminal_id int,
    @terminal_row_id bigint,
    @timestamp datetime2(3),
    @id int,
    @event int
)
as
    declare @vcm_id int = 0

    select
        @vcm_id = [address]
    from dim.se se
    join dim.network net
        on se.terminal_id = net.terminal_id and se.network = net.id
    where se.terminal_id = @terminal_id
        and se.se = @id
        and network_type = 6

    insert into fact.se
    (
        terminal_id,
        terminal_row_id,
        [timestamp],
        se,
        event_id,
        repeat_count,
        error_code,
        network,
        vcm_id
    )
    values
    (
        @terminal_id,
        @terminal_row_id,
        @timestamp,
        @id,
        @event,--event_id,
        0,--repeat_count,
        0,--error_code,
        (select d.network from dim.se d where d.terminal_id = @terminal_id and d.se = @id),--network,
        @vcm_id
    )
go
  • The tables and related indexed view definitions:
create table fact.sequence
(
    terminal_id int not null,
    terminal_row_id bigint not null,
    [timestamp] datetime2(3) not null,

    sequence_id int not null,
    event_type_id int not null,
    pred_kwh int not null,
    pred_dv_count int not null,
    pred_duration int not null, --seconds
    pred_collected_weight int not null, --kg
    actual_kwh int not null,
    actual_dv_count int not null,
    actual_duration int not null, --seconds
    actual_collected_weight int not null, --kg

    constraint pk__fact_sequence primary key (terminal_id, terminal_row_id),
    constraint fk__fact_sequence__dim_sequence foreign key (terminal_id, sequence_id) references dim.sequence(terminal_id, id),
    constraint fk__fact_sequence__enum_sequence_event foreign key (event_type_id) references enum.sequence_event (id)
)

go
create view staging.v_daily_fact_sequence
with schemabinding
as
    SELECT
        cast(fs.[timestamp] as date) [date],
        fs.terminal_id,
        fs.sequence_id,
        fs.event_type_id,
        count_big(*) as [count],
        sum(fs.actual_kwh) sum_kwh,
        sum(fs.actual_dv_count) sum_dv_count,
        sum(fs.actual_duration) sum_duration,
        sum(fs.actual_collected_weight) sum_kg
    FROM [fact].[sequence] fs
    group by
        cast([timestamp] as date),
        fs.terminal_id,
        sequence_id,
        event_type_id
go
create unique clustered index uci__staging__fact_sequence on staging.v_daily_fact_sequence([date], terminal_id, sequence_id, event_type_id)
go



create table fact.se
(
    terminal_id int not null,
    terminal_row_id bigint not null,
    [timestamp] datetime2(3) not null,

    se int not null,
    event_id int not null,
    repeat_count int not null,
    error_code int not null,
    network int not null,
    vcm_id int not null,

    constraint pk__fact_se primary key (terminal_id, terminal_row_id),
    constraint fk__fact_se__dim_se foreign key (terminal_id, se) references dim.se(terminal_id, se),
    constraint fk__fact_se__enum_valve_event foreign key (event_id) references enum.valve_event (id)
)

go
create view staging.v_daily_fact_se
with schemabinding
as
    select
        cast([timestamp] as date) [date],
        terminal_id,
        se,
        event_id,
        count_big(*) as [count]
    from fact.se
    group by
        cast([timestamp] as date),
        terminal_id,
        se,
        event_id
go
create unique clustered index uci__staging__fact_se on staging.v_daily_fact_se([date], terminal_id, se, event_id)
go
<deadlock>
  <victim-list>
    <victimProcess id="process2742b6a5848" />
  </victim-list>
  <process-list>
    <process id="process2742b6a5848" taskpriority="0" logused="351972" waitresource="KEY: 5:72057594049855488 (1c280247b0f1)" waittime="2388" ownerId="8532120" transactionname="user_transaction" lasttranstarted="2022-11-02T11:48:16.683" XDES="0x273c207c428" lockMode="RangeS-U" schedulerid="11" kpid="30304" status="suspended" spid="61" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2022-11-02T11:48:17.697" lastbatchcompleted="2022-11-02T11:48:17.697" lastattention="1900-01-01T00:00:00.697" clientapp="Python" hostname="ENE-5CD9245PJR" hostpid="30564" loginname="etl" isolationlevel="read committed (2)" xactid="8532120" currentdb="5" currentdbname="EDW" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
      <executionStack>
        <frame procname="EDW.ETL_1.7.1.log_sequence_event" line="50" stmtstart="2510" stmtend="4352" sqlhandle="0x03000500e1ab652609eeba0041af000001000000000000000000000000000000000000000000000000000000">
insert into fact.sequence
        (
            terminal_id,
            terminal_row_id,
            [timestamp],
            sequence_id,
            event_type_id,
            pred_kwh,
            pred_dv_count,
            pred_duration,
            pred_collected_weight,
            actual_kwh,
            actual_dv_count,
            actual_duration,
            actual_collected_weight
        )
        values
        (
            @terminal_id,--terminal_id,
            @terminal_row_id,--terminal_row_id,
            @timestamp,--[timestamp],
            @id,--sequence_id,
            @event,--event_type_id,
            0,--pred_kwh,
            0,--pred_dv_count,
            0,--pred_duration,
            0,--pred_collected_weight,
            @energy,--actual_kwh,
            @no_of_dvs,--actual_dv_count,
            @duration,--actual_duration,
            @weight--actual_collected_weight    </frame>
        <frame procname="adhoc" line="1" stmtstart="218" stmtend="588" sqlhandle="0x0100050095e97700e09e97017402000000000000000000000000000000000000000000000000000000000000">
EXEC [ETL_1.7.1].log_sequence_event @timestamp=@P1,@id=@P2,@event=@P3,@energy=@P4,@duration=@P5,@weight=@P6,@no_of_dvs=@P7,@average_fill_degree=@P8,@terminal_id=@P9,@terminal_row_id=@P1    </frame>
        <frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">
unknown    </frame>
      </executionStack>
      <inputbuf>
(@P1 nvarchar(46),@P2 int,@P3 int,@P4 int,@P5 int,@P6 int,@P7 int,@P8 int,@P9 int,@P10 bigint)set nocount on;EXEC [ETL_1.7.1].log_sequence_event @timestamp=@P1,@id=@P2,@event=@P3,@energy=@P4,@duration=@P5,@weight=@P6,@no_of_dvs=@P7,@average_fill_degree=@P8,@terminal_id=@P9,@terminal_row_id=@P10   </inputbuf>
    </process>
    <process id="process2742b06d468" taskpriority="0" logused="770436" waitresource="KEY: 5:72057594049658880 (ffffffffffff)" waittime="2426" ownerId="8529120" transactionname="user_transaction" lasttranstarted="2022-11-02T11:48:15.520" XDES="0x273c2164428" lockMode="RangeS-U" schedulerid="4" kpid="36140" status="suspended" spid="60" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2022-11-02T11:48:17.657" lastbatchcompleted="2022-11-02T11:48:17.657" lastattention="1900-01-01T00:00:00.657" clientapp="Python" hostname="ENE-5CD9245PJR" hostpid="30564" loginname="etl" isolationlevel="read committed (2)" xactid="8529120" currentdb="5" currentdbname="EDW" lockTimeout="4294967295" clientoption1="673185824" clientoption2="128056">
      <executionStack>
        <frame procname="EDW.ETL_1.7.1.log_se_event" line="22" stmtstart="872" stmtend="1872" sqlhandle="0x03000500c4f6a02105eeba0041af000001000000000000000000000000000000000000000000000000000000">
insert into fact.se
    (
        terminal_id,
        terminal_row_id,
        [timestamp],
        se,
        event_id,
        repeat_count,
        error_code,
        network,
        vcm_id
    )
    values
    (
        @terminal_id,
        @terminal_row_id,
        @timestamp,
        @id,
        @event,--event_id,
        0,--repeat_count,
        0,--error_code,
        (select d.network from dim.se d where d.terminal_id = @terminal_id and d.se = @id),--network,
        @vcm_id    </frame>
        <frame procname="adhoc" line="1" stmtstart="136" stmtend="336" sqlhandle="0x01000500b1ea553470ff35ee7302000000000000000000000000000000000000000000000000000000000000">
EXEC [ETL_1.7.1].log_se_event @timestamp=@P1,@id=@P2,@event=@P3,@terminal_id=@P4,@terminal_row_id=@P    </frame>
        <frame procname="unknown" line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000">
unknown    </frame>
      </executionStack>
      <inputbuf>
(@P1 nvarchar(46),@P2 int,@P3 int,@P4 int,@P5 bigint)set nocount on;EXEC [ETL_1.7.1].log_se_event @timestamp=@P1,@id=@P2,@event=@P3,@terminal_id=@P4,@terminal_row_id=@P5   </inputbuf>
    </process>
  </process-list>
  <resource-list>
    <keylock hobtid="72057594049855488" dbid="5" objectname="EDW.staging.v_daily_fact_sequence" indexname="uci__staging__fact_sequence" id="lock2740ecc4e00" mode="X" associatedObjectId="72057594049855488">
      <owner-list>
        <owner id="process2742b06d468" mode="X" />
      </owner-list>
      <waiter-list>
        <waiter id="process2742b6a5848" mode="RangeS-U" requestType="wait" />
      </waiter-list>
    </keylock>
    <keylock hobtid="72057594049658880" dbid="5" objectname="EDW.staging.v_daily_fact_se" indexname="uci__staging__fact_se" id="lock27317245700" mode="RangeS-U" associatedObjectId="72057594049658880">
      <owner-list>
        <owner id="process2742b6a5848" mode="RangeS-U" />
      </owner-list>
      <waiter-list>
        <waiter id="process2742b06d468" mode="RangeS-U" requestType="wait" />
      </waiter-list>
    </keylock>
  </resource-list>
</deadlock>
7
  • Do you commit after each proc call? Do the procs touch other tables before the insert?
    – Dan Guzman
    Nov 3, 2022 at 9:17
  • I commit after each batch which is maximum 2000 calls. log_se_event makes a select from the tables dim.se and dim.network before the insert, sequences has no connection to those two tables. I've updated the question with this info. Nov 3, 2022 at 9:56
  • Are there any other objects in place that can connect any of the se to sequence objects, such as foreign keys, check constraints, triggers, etc? Or are you sure all se objects are completely isolated from all sequence objects?
    – J.D.
    Nov 3, 2022 at 12:44
  • it's a little odd that both owner and victim processes have two open transactions. can you post the code that leads to the deadlocks? Nov 3, 2022 at 13:51
  • 1
    autocommit=off so @@trancount is going to be 2. Nov 3, 2022 at 14:46

1 Answer 1

2

Since you have autocommit off, you're probably writing a transaction runs both stored procedures, and still holds locks from a previous invocation.

So a session that owns an X lock on v_daily_fact_se tries to get a range lock v_daily_fact_sequence, but another session already owns an X lock on a key in the range, and so becomes blocked. Then the session owning the X lock on v_daily_fact_sequence tries to acquire a range lock on v_daily_fact_se and becomes blocked by the first session.

So audit your python code to ensure that no session writes to both tables in a transaction.

1
  • That would explain it since it can definitely happen that two threads write to the same table during sessions that overlap in time. I guess I got to hung up on the fact that the deadlock report mentioned these two unrelated procedures. Nov 3, 2022 at 15:01

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.