程序中的查询偶尔没有完成

Question

我有一个关于如何在运行查询的 SQL Server 2008 R2（标准版）中调试非常奇怪的行为（嵌套查询卡住）的问题。

有时（不幸的是并非总是如此）当我运行一个复杂的过程来执行一些数据转换时，涉及：

-- Update of statistics.
EXEC sp_updatestats;

-- Run of another procedure with single complex query
-- procedure declared with recompile.
EXEC usp_query_procedure;

我遇到了这个过程没有完成的问题（典型的时间 < 1 秒，当卡住时，运行时间可能是几天，还没有完成）。

如果我取出查询文本并单独运行它，它会在一秒钟内完成，但如果我在程序中运行它，它就会卡住。

当这些症状开始我没有任何WITH RECOMPILE或sp_updatestats。我搜索了一下，发现可能会使用缓存的错误执行计划（对于某些输入参数），并且重新编译会有所帮助（前提是统计信息已更新）。虽然这两个选项似乎减轻了这个问题（它发生的频率较低），但它确实没有完全消失。为什么它在所有情况下都没有帮助？还有什么可能导致这个问题？

当该过程“卡住”并且我附加了一个 SQL Profiler 时，我可以看到每个刷新滴答声的数千个锁定 acuqires/释放。当查询正常运行时，只有一小部分已使用的锁，但这可能很明显。

同样非常奇怪的是，这种情况只发生在运行相同应用程序（标准版/企业版混合版）的四台服务器中的一台（标准版）上。

我该如何进一步调试？我应该登录探查器的哪些事件才能查看导致问题的原因？这里的其他人有没有发生过类似的事情？

请甚至暗示谷歌什么，寻找什么，追踪什么可以导致解决方案。如果我设法解决了这个问题，我一定会在这里发布我的发现以供后代使用。

Answer 1

在这一点上，我不会打扰使用 Profiler。您可能只是在激怒这个问题，因为通过 UI 将其流式传输回资源并不完全是轻量级的。如果要跟踪，请设置服务器端跟踪并随后检查结果。

但首先，让我们从更简单的开始。当程序以“卡住”状态运行时，查看DMVsys.dm_exec_requests。您想查看它在等待什么 ( wait_type, last_wait_type) 以及它是否被另一个会话阻止 ( blocking_session_id)。您还可以查看会话的某些SET设置（quoted_identifier、arithabort等）与计划（您可以通过迂回的方式从中获得sys.dm_exec_plan_attributes）和存储过程本身的设置（其中一些您可以使用）不同OBJECTPROPERTY()。

例如，让我们仅比较程序、会话和计划的一些设置。首先，当查询永远运行时（并假设您知道 spid；我假设这里是 67），从sys.dm_exec_requests和检查这些值sys.dm_exec_sessions：

SELECT [status], wait_type, last_wait_type, plan_handle, blocking_session_id
  FROM sys.dm_exec_requests 
  WHERE session_id = 67;

SELECT [quoted_identifier], [arithabort], [ansi_nulls], [date_format]
  FROM sys.dm_exec_sessions 
  WHERE session_id = 67;

现在，这可能会立即告诉您在哪里查找问题：您可能有一个wait_type指示存在 I/O 问题，或者您可能会看到会话被阻止 - 在这种情况下，您可以调查该会话是什么( blocking_session_id)是在做。

如果这些信息都没有用，让我们继续执行计划。计划的一个常见问题是它们可能因各种SET选项而异，这可能导致两个不同用户或应用程序和 SSMS 的性能截然不同。

0x00...在上面的结果中，计划句柄将是一个很大的varbinary 值。您可以将其复制并粘贴到此查询中：

SELECT 
  [quoted_identifier] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        64 & CONVERT(INT, a.value) END = 64 THEN 1 ELSE 0 END),
  [arithabort] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        4096 & CONVERT(INT, a.value) END = 4096 THEN 1 ELSE 0 END),
  [ansi_nulls] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        32 & CONVERT(INT, a.value) END = 32 THEN 1 ELSE 0 END),
  [date_format] = MAX(CASE WHEN attribute = 'date_format' THEN 
        CONVERT(INT, a.value) END)
FROM sys.dm_exec_cached_plans AS p
CROSS APPLY sys.dm_exec_plan_attributes(p.plan_handle) AS a

WHERE p.plan_handle = 0x... --<-- *** put the plan handle here ***

AND a.attribute IN ('set_options', 'date_format');

您可以将这些结果与您在上面提取的会话值进行比较，并且其中一些属性与过程本身一起存储：

SELECT OBJECTPROPERTY(OBJECT_ID('dbo.usp_query_procedure'), 'IsQuotedIdentOn');
SELECT OBJECTPROPERTY(OBJECT_ID('dbo.usp_query_procedure'), 'ExecIsQuotedIdentOn');

您还可以对为同一过程找到的任何其他计划重复该查询，以查看实际上是否存在使用不同设置执行该过程的情况：

SELECT 
  p.plan_handle,
  [quoted_identifier] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        64 & CONVERT(INT, a.value) END = 64 THEN 1 ELSE 0 END),
  [arithabort] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        4096 & CONVERT(INT, a.value) END = 4096 THEN 1 ELSE 0 END),
  [ansi_nulls] = MAX(CASE WHEN 
      CASE WHEN attribute = 'set_options' THEN 
        32 & CONVERT(INT, a.value) END = 32 THEN 1 ELSE 0 END),
  [date_format] = MAX(CASE WHEN attribute = 'date_format' THEN 
        CONVERT(INT, a.value) END)
FROM sys.dm_exec_cached_plans AS p
CROSS APPLY sys.dm_exec_plan_attributes(p.plan_handle) AS a
INNER JOIN sys.dm_exec_procedure_stats AS s
ON p.plan_handle = s.plan_handle
AND s.[object_id] = OBJECT_ID('dbo.usp_query_procedure')
AND a.attribute IN ('set_options', 'date_format')
GROUP BY p.plan_handle; 

如果您看到多个结果，请检查每一列。任何一个计划显示 1 而另一个计划显示 0 的列对我来说都是可疑的。

同时，您可以阅读一些关于此问题和类似问题的精彩帖子：

http://www.sommarskog.se/query-plan-mysteries.html

http://www.simple-talk.com/sql/t-sql-programming/dmvs-for-query-plan-metadata/

http://www.benjaminnevarez.com/2011/09/parameter-sniffing-and-plan-reuse-affecting-set-options/

是的，sp_WhoIsActive可能也会让您深入了解正在发生的事情。