SQL Server 性能：PREEMPTIVE_OS_DELETESECURITYCONTEXT 显性等待类型

Question

我昨天接到一位客户的电话，他抱怨 SQL Server 的 CPU 使用率过高。我们使用的是 SQL Server 2012 64 位 SE。服务器运行 Windows Server 2008 R2 Standard、2.20 GHz Intel Xeon（4 核）、16 GB RAM。

在确定罪魁祸首实际上是 SQL Server 之后，我使用此处的 DMV 查询查看了等待实例的顶部。前两个等待是： (1)PREEMPTIVE_OS_DELETESECURITYCONTEXT和 (2) SOS_SCHEDULER_YIELD。

编辑：这是“顶部等待查询”的结果（尽管今天早上有人违背我的意愿重新启动了服务器）：

我们做了很多密集的计算/转换，所以我可以理解SOS_SCHEDULER_YIELD。但是，我很好奇PREEMPTIVE_OS_DELETESECURITYCONTEXT等待类型以及为什么它可能是最高的。

我可以在此处找到关于此等待类型的最佳描述/讨论。它提到：

PREEMPTIVE_OS_ 等待类型是离开数据库引擎的调用，通常是到 Win32 API，并且在 SQL Server 之外为各种任务执行代码。在这种情况下，它正在删除以前用于远程资源访问的安全上下文。相关的API其实叫做DeleteSecurityContext()

据我所知，我们没有任何外部资源，如链接服务器或文件表。而且我们不进行任何模拟等操作。备份是否会导致此峰值或域控制器出现故障？

到底是什么导致这成为主要的等待类型？如何进一步跟踪这种等待类型？

编辑 2：我检查了 Windows 安全日志的内容。我看到一些可能感兴趣的条目，但我不确定这些是否正常：

Special privileges assigned to new logon.

Subject:
    Security ID:        NT SERVICE\MSSQLServerOLAPService
    Account Name:       MSSQLServerOLAPService
    Account Domain:     NT Service
    Logon ID:       0x3143c

Privileges:     SeImpersonatePrivilege

Special privileges assigned to new logon.

Subject:
    Security ID:        NT SERVICE\MSSQLSERVER
    Account Name:       MSSQLSERVER
    Account Domain:     NT Service
    Logon ID:       0x2f872

Privileges:     SeAssignPrimaryTokenPrivilege
            SeImpersonatePrivilege

编辑 3：@Jon Seigel，按照您的要求，这里是您的查询结果。与保罗的有点不同：

编辑 4：我承认，我是第一次使用扩展事件用户。我将此等待类型添加到 wait_info_external 事件并看到了数百个条目。没有 sql 文本或计划句柄，只有一个调用堆栈。我怎样才能进一步追查源头？

Answer 1

根据标题，我知道这个问题主要与 PREEMPTIVE_OS_DELETESECURITYCONTEXT 等待类型有关，但我认为这是对真正问题的误导，即“一位客户抱怨其 SQL Server 上的 CPU 使用率过高”。

我认为关注这种特定的等待类型是徒劳无益的，因为它会随着每个连接的建立而上升。我在我的笔记本电脑上运行以下查询（这意味着我是唯一的用户）：

SELECT * 
FROM sys.dm_os_wait_stats
WHERE wait_type = N'PREEMPTIVE_OS_DELETESECURITYCONTEXT'

然后我执行以下任一操作并重新运行此查询：

• 打开一个新的查询选项卡
• 关闭新的查询选项卡
• 从 DOS 提示符运行以下命令：SQLCMD -E -Q "select 1"

现在，我们知道 CPU 很高，因此我们应该查看正在运行的内容，看看哪些会话的 CPU 很高：

SELECT req.session_id AS [SPID],
       req.blocking_session_id AS [BlockedBy],
       req.logical_reads AS [LogReads],
       DB_NAME(req.database_id) AS [DatabaseName],
       SUBSTRING(txt.[text],
                 (req.statement_start_offset / 2) + 1,
                 CASE
                     WHEN req.statement_end_offset > 0
                        THEN (req.statement_end_offset - req.statement_start_offset) / 2
                     ELSE LEN(txt.[text])
                 END
                ) AS [CurrentStatement],
       txt.[text] AS [CurrentBatch],
       CONVERT(XML, qplan.query_plan) AS [StatementQueryPlan],
       OBJECT_NAME(qplan.objectid, qplan.[dbid]) AS [ObjectName],
       sess.[program_name],
       sess.[host_name],
       sess.nt_user_name,
       sess.total_scheduled_time,
       sess.memory_usage,
       req.*
FROM sys.dm_exec_requests req
INNER JOIN sys.dm_exec_sessions sess
        ON sess.session_id = req.session_id
CROSS APPLY sys.dm_exec_sql_text(req.[sql_handle]) txt
OUTER APPLY sys.dm_exec_text_query_plan(req.plan_handle,
                                        req.statement_start_offset,
                                        req.statement_end_offset) qplan
WHERE req.session_id <> @@SPID
ORDER BY req.logical_reads DESC, req.cpu_time DESC
--ORDER BY req.cpu_time DESC, req.logical_reads DESC

我通常按​​原样运行上述查询，但您也可以切换注释掉哪个 ORDER BY 子句，看看是否会给出更有趣/有用的结果。

或者，您可以根据 dm_exec_query_stats 运行以下命令来查找成本最高的查询。下面的第一个查询将向您显示各个查询（即使它们有多个计划），并按平均 CPU 时间排序，但您可以轻松地将其更改为平均逻辑读取数。一旦发现某个查询看起来占用了大量资源，请将“sql_handle”和“statement_start_offset”复制到下面第二个查询的 WHERE 条件中以查看各个计划（可以超过 1）。滚动到最右侧，假设有一个 XML 计划，它将显示为一个链接（在网格模式下），如果您单击它，它将带您进入计划查看器。

查询#1：获取查询信息

;WITH cte AS
(
   SELECT qstat.[sql_handle],
          qstat.statement_start_offset,
          qstat.statement_end_offset,
          COUNT(*) AS [NumberOfPlans],
          SUM(qstat.execution_count) AS [TotalExecutions],

          SUM(qstat.total_worker_time) AS [TotalCPU],
          (SUM(qstat.total_worker_time * 1.0) / SUM(qstat.execution_count)) AS [AvgCPUtime],
          MAX(qstat.max_worker_time) AS [MaxCPU],

          SUM(qstat.total_logical_reads) AS [TotalLogicalReads],
   (SUM(qstat.total_logical_reads * 1.0) / SUM(qstat.execution_count)) AS [AvgLogicalReads],
          MAX(qstat.max_logical_reads) AS [MaxLogicalReads],

          SUM(qstat.total_rows) AS [TotalRows],
          (SUM(qstat.total_rows * 1.0) / SUM(qstat.execution_count)) AS [AvgRows],
          MAX(qstat.max_rows) AS [MaxRows]
   FROM sys.dm_exec_query_stats  qstat
   GROUP BY qstat.[sql_handle], qstat.statement_start_offset, qstat.statement_end_offset
)
SELECT  cte.*,
        DB_NAME(txt.[dbid]) AS [DatabaseName],
        SUBSTRING(txt.[text],
                  (cte.statement_start_offset / 2) + 1,
                  CASE
                      WHEN cte.statement_end_offset > 0
                          THEN (cte.statement_end_offset - cte.statement_start_offset) / 2
                      ELSE LEN(txt.[text])
                  END
                 ) AS [CurrentStatement],
        txt.[text] AS [CurrentBatch]
FROM cte
CROSS APPLY sys.dm_exec_sql_text(cte.[sql_handle]) txt
ORDER BY cte.AvgCPUtime DESC

查询#2：获取计划信息

SELECT  *,
        DB_NAME(qplan.[dbid]) AS [DatabaseName],
        CONVERT(XML, qplan.query_plan) AS [StatementQueryPlan],
        SUBSTRING(txt.[text],
                  (qstat.statement_start_offset / 2) + 1,
                  CASE
                        WHEN qstat.statement_end_offset > 0
                        THEN (qstat.statement_end_offset - qstat.statement_start_offset) / 2
                        ELSE LEN(txt.[text])
                  END
                 ) AS [CurrentStatement],
        txt.[text] AS [CurrentBatch]
FROM sys.dm_exec_query_stats  qstat
CROSS APPLY sys.dm_exec_sql_text(qstat.[sql_handle]) txt
OUTER APPLY sys.dm_exec_text_query_plan(qstat.plan_handle,
                                        qstat.statement_start_offset,
                                        qstat.statement_end_offset) qplan
-- paste info from Query #1 below
WHERE qstat.[sql_handle] = 0x020000001C70C614D261C85875D4EF3C90BD18D02D62453800....
AND qstat.statement_start_offset = 164
-- paste info from Query #1 above
ORDER BY qstat.total_worker_time DESC