尽管 cpu_time 和逻辑读/写非常低，但存储过程仍超时

Question

我正在本地开发一项使用 SQL Server Express 作为数据库的服务。我看到奇怪的行为，存储过程连续执行多次（使用不同的参数），并且在几次成功调用（每次调用大约 1 秒）之后，它开始超时。

rpc_completed 事件显示以下信息：

CPU时间	逻辑读取数	期间	结果
984000	15244	1048445	好的
63000	8543	75841	好的
531000	1782	30036796	中止
0	2	30003296	中止
15000	820	29995839	中止
0	2	30010495	中止

四个中止的事件是完全相同的命令+参数的重试。

这里发生了一些奇怪的事情：

• cpu_time始终低于 1 秒，即使duration跳至 30 秒
• 两个中止的事件显示 0cpu_time并且仅显示 2 logical reads（应该是数千）

这只是一个在开发机器上运行的简单 SQL Express 实例，没有进行任何其他操作。整个数据库只有几 MB，因此很难想象这些命令的成本会稍微昂贵。所以我不确定为什么服务器突然开始在这些命令上超时（虽然显然几乎没有做任何工作）。

知道这是怎么回事吗？

更新1：

• 稍后我从查询窗口运行了失败的命令，它在 1 秒内成功执行。所以这并不是一个本质上昂贵的命令。
• 整个数据库只有大约 5000 行。
• 该命令仅引用 6 个表。

该命令如下所示：

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

存储过程 GetDataRelationships 如下所示：

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

示例输出：

组ID	启动PID	物品种类	物品ID	修改日期	已删除	参考字段名称	参考项类型	参考项目ID
1234	2345	F	3456	2023-01-01 02:34:56	0	相关P1ID	磷	2345
1234	2345	F	3456	2023-01-01 02:34:56	0	相关P2ID	磷	4567
...

更新2：

我刚刚在启用实际执行计划的情况下再次从 SSMS 运行该命令并得到以下结果：

• 经过时间：00:00:15.509（不是 30 秒，但仍然很长）
• 返回的行数：1166
• 查询1-100：
  • 估计子树成本：0.0100022（每个）
  • 查询成本（相对于批次）：0%
• 查询 101：
  • 估计子树成本：2.98618
  • 查询成本（相对于批次）：75%

从实际执行计划来看：

        <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>

我可以看到有一个小的（269 毫秒）ASYNC_NETWORK_IO 等待，可能只是 SSMS 拉取/显示查询结果有点慢，但我不知道另外 14 秒来自哪里。实际计划中的查询耗时仅为375毫秒，而连接耗时为15秒。

更新3：

我检查了 sys.dm_exec_session_wait_stats 以获取有关上述执行 (63) 的 SPID 的信息，并得到了这些数字：

会话ID	等待类型	等待任务数	等待时间毫秒	最大等待时间毫秒	信号等待时间毫秒
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

看起来我发现从 SSMS 手动执行缺少 14 秒（不知道为什么实际查询计划 WaitStats 中没有提到这一点），但我不确定服务尝试执行此命令时是否原始超时有同样的原因。

我怀疑某些模糊的 SQL Server Express 限制是原因，但我找不到任何看起来相关的限制。

更新4： 转移注意力。看起来 SSMS 中大约 15 秒的执行时间只是由于请求实际的执行计划。每次都会发生。禁用该选项，执行时间始终小于 1 秒。

Answer 1

当查询持续时间增加但没有执行任何操作（CPU 或读取增加）时，它会等待。

您必须弄清楚它在等待什么 - 如果它正在阻塞（锁定等待）资源或其他东西（可能是 Express 版本限制）。

如果您可以使用 XE 会话中的命令 + 参数重现您的问题，那么实际的执行计划将保存等待信息。

另一种选择是，如果您在该数据库上启用了查询存储（+查询存储等待统计信息收集），则可以在那里找到信息。尽管查询被聚合，但等待被分组为一般类别。

AFAIK 没有有效的方法将 XE 中的过程调用与其等待关联起来。您必须启用因果关系跟踪并收集所有等待，这通常是不可行的。