2

I'm developing a service locally that uses SQL Server Express as a database. I'm seeing strange behavior where a stored procedure is executing several times in a row (with different parameters), and after a few successful calls that take ~1 sec each, it starts timing out.

The rpc_completed events show the following info:

cpu_time logical_reads duration result
984000 15244 1048445 OK
63000 8543 75841 OK
531000 1782 30036796 Abort
0 2 30003296 Abort
15000 820 29995839 Abort
0 2 30010495 Abort

The four aborted events were retries of the exact same command + parameters.

There are several odd things going on here:

  • cpu_time is always under 1 sec, even when duration jumps to 30 sec
  • two aborted events show 0 cpu_time and only 2 logical reads (should be thousands)

This is just a simple SQL Express instance running on a development machine with nothing else going on. The entire database is only a few MB, so it's hard to image any of these commands being even mildly expensive. So I'm not sure why the server suddenly starts timing out on these commands (while apparently doing almost no work).

Any idea what's going on here?

UPDATE 1:

  • I ran the failed command a bit later from a query window and it executed successfully in <1 sec. So it's not an inherently expensive command.
  • The entire database only has ~5000 rows in it.
  • The command only references 6 tables.

The command looks like this:

declare @p1 KeyType
insert into @p1 values (1234,2345)
insert into @p1 values (1234,3456)
...
(100 rows)
...
insert into @p1 values (1234,7890)
exec GetDataRelationships @startKeys=@p1

The stored procedure GetDataRelationships looks like this:

CREATE PROCEDURE [dbo].[GetDataRelationships]
    @startKeys dbo.KeyType READONLY
AS
    -- Gets a flat list of item + reference rows representing the specified start items (P) and all items directly or indirectly 
    -- related to them, along with the references that relate them.

    WITH startP AS (
        SELECT p.*, StartPID = pr.ItemID
        FROM PTable p
            JOIN @startKeys pr ON pr.GroupID = p.GroupID AND pr.ItemID = p.PID
    ),
    FtoP AS (
        SELECT f.*, StartPID = pr.ItemID
        FROM FTable f
            JOIN @startKeys pr ON pr.GroupID = f.GroupID AND pr.ItemID = f.RelatedP1ID
        UNION
        SELECT f.*, StartPID = pr.ItemID
        FROM FTable f
            JOIN @startKeys pr ON pr.GroupID = f.GroupID AND pr.ItemID = f.RelatedP2ID
    ),
    ...
    (12 more subqueries following table relationships)
    ...
    -- start P
    SELECT sp.GroupID, sp.StartPID, ItemType = 'P', ItemID = sp.ItemID, sp.ModifiedDate, sp.Deleted, RefFieldName = CAST(NULL AS varchar(20)), RefItemType = CAST(NULL AS char), RefItemID = CAST(NULL AS int)
    FROM startP sp
    UNION 
    -- related F to P1
    SELECT sf.GroupID, sf.StartPersonID, 'F', sf.FID, sf.ModifiedDate, sf.Deleted, 'P1ID', 'P', sf.P1ID
    FROM FtoP sf
    WHERE sf.P1ID = sf.StartPID
    UNION 
    -- related F to P2
    SELECT sf.GroupID, sf.StartPID, 'F', sf.FID, sf.ModifiedDate, sf.Deleted, 'P2ID', 'P', sf.P2ID
    FROM FtoP sf
    WHERE sf.P2ID = sf.StartPID
    UNION 
    ...
    (18 more UNION subqueries)
    ...

RETURN 0

Sample output:

GroupID StartPID ItemType ItemID ModifiedDate Deleted RefFieldName RefItemType RefItemID
1234 2345 F 3456 2023-01-01 02:34:56 0 RelatedP1ID P 2345
1234 2345 F 3456 2023-01-01 02:34:56 0 RelatedP2ID P 4567
...

UPDATE 2:

I just ran the command again from SSMS with Actual Execution Plan enabled and got these results:

  • Elapsed time: 00:00:15.509 (it's not 30 sec but it's still long)
  • Rows returned: 1166
  • Query 1-100:
    • Estimated subtree cost: 0.0100022 (each)
    • Query cost (relative to the batch): 0%
  • Query 101:
    • Estimated subtree cost: 2.98618
    • Query cost (relative to the batch): 75%

From the Actual Execution Plan:

        <StmtSimple StatementCompId="103" StatementEstRows="860.45" StatementId="101" StatementOptmLevel="FULL" StatementOptmEarlyAbortReason="TimeOut" CardinalityEstimationModelVersion="150" StatementSubTreeCost="2.98618" StatementText="...<snip>..." StatementType="SELECT" QueryHash="0x358148098B8FEF90" QueryPlanHash="0xF78E3AAD5E94ED14" RetrievedFromCache="true" SecurityPolicyApplied="false">
          <StatementSetOptions ANSI_NULLS="true" ANSI_PADDING="true" ANSI_WARNINGS="true" ARITHABORT="true" CONCAT_NULL_YIELDS_NULL="true" NUMERIC_ROUNDABORT="false" QUOTED_IDENTIFIER="true" />
          <QueryPlan DegreeOfParallelism="0" NonParallelPlanReason="NoParallelPlansInDesktopOrExpressEdition" MemoryGrant="17600" CachedPlanSize="1472" CompileTime="575" CompileCPU="575" CompileMemory="25864">
            <Warnings>
              <MemoryGrantWarning GrantWarningKind="Excessive Grant" RequestedMemory="17600" GrantedMemory="17600" MaxUsedMemory="808" />
            </Warnings>
            <MemoryGrantInfo SerialRequiredMemory="16256" SerialDesiredMemory="17600" RequiredMemory="16256" DesiredMemory="17600" RequestedMemory="17600" GrantWaitTime="0" GrantedMemory="17600" MaxUsedMemory="808" MaxQueryMemory="494904" />
            <OptimizerHardwareDependentProperties EstimatedAvailableMemoryGrant="206463" EstimatedPagesCached="103231" EstimatedAvailableDegreeOfParallelism="4" MaxCompileMemory="1951112" />
            <OptimizerStatsUsage>
              <!-- ...<snip>... -->
            </OptimizerStatsUsage>
            <TraceFlags IsCompileTime="true">
              <TraceFlag Value="8017" Scope="Global" />
            </TraceFlags>
            <TraceFlags IsCompileTime="false">
              <TraceFlag Value="8017" Scope="Global" />
            </TraceFlags>
            <WaitStats>
              <Wait WaitType="ASYNC_NETWORK_IO" WaitTimeMs="269" WaitCount="2" />
            </WaitStats>
            <QueryTimeStats CpuTime="106" ElapsedTime="375" />
            <RelOp AvgRowSize="57" EstimateCPU="0.00115408" EstimateIO="0" EstimateRebinds="0" EstimateRewinds="0" EstimatedExecutionMode="Row" EstimateRows="860.45" LogicalOp="Aggregate" NodeId="0" Parallel="false" PhysicalOp="Stream Aggregate" EstimatedTotalSubtreeCost="2.98618">
              <!-- ...<snip>... -->
            </RelOp>
          </QueryPlan>
        </StmtSimple>

I can see there's a small (269 ms) ASYNC_NETWORK_IO wait, probably just SSMS being a bit slow pulling/displaying the query results, but I don't see where the other 14 seconds came from. Query elapsed time in the actual plan is only 375 ms, while the connection elapsed time 15 sec.

UPDATE 3:

I checked sys.dm_exec_session_wait_stats for info on the SPID for the above execution (63), and got these numbers:

session_id wait_type waiting_tasks_count wait_time_ms max_wait_time_ms signal_wait_time_ms
63 PAGELATCH_SH 2 0 0 0
63 PAGELATCH_EX 4 0 0 0
63 SOS_SCHEDULER_YIELD 194 1 0 1
63 MEMORY_ALLOCATION_EXT 9189 21 3 0
63 RESERVED_MEMORY_ALLOCATION_EXT 390 0 0 0
63 ASYNC_NETWORK_IO 219 13787 1307 8

Looks like I found the missing 14 sec for the manual execution from SSMS (not sure why this wasn't mentioned in the actual query plan WaitStats), but I'm not sure if the original timeouts when the service was trying to execute this command had the same cause.

I'm suspicious of some obscure SQL Server Express limit being the cause, but I can't find any limits that looks relevant.

UPDATE 4: Red herring. Looks like the ~15 sec execution time in SSMS is just due to requesting the actual execution plan. Happens every time. Disable that option and the execution time is consistently < 1 sec.

1
  • None of the tables are partitioned. This is a super basic database.
    – Bob Meyers
    Feb 13, 2023 at 18:10

1 Answer 1

6

When the query duration is increasing but otherwise not doing anything (increase in CPU or reads), it's waiting.

You have to figure out what it's waiting on - if it's blocking (Lock waits) resources or something else (maybe Express version throttling).

If you can repro your problem using the command + parameters from your XE session, then the actual execution plan holds the wait information.

Another option is if you have Query Store (+ Query Store wait stats collection) enabled on that database, you can find information there. Though the queries are aggregated, and Waits are grouped into general categories.

AFAIK there is no efficient way to correlate a procedure call in XE with its waits. You would have to enable causality tracking and collect all the waits which is usually not feasible.

1

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.