对连接到 sys.databases 的查询统计和执行计划运行针对 DMV 的查询

Dia*_*ane 6 performance sql-server execution-plan dmv query-performance

我最初在 Twitter #sqlhelp 中将此作为一个不同的问题发布,但想以不同的方式发布在这里。

我正在尝试使用 DMV dm_exec_query_statsdm_exec_cached_plansdm_exec_sql_text以及最初的sys.databases创建一个跟踪各种统计数据(例如读取、写入、CPU、执行计数等)性能最差的语句的作业。

发生的情况是,这个查询有时(并非总是)在繁忙的服务器上运行需要超过 8 分钟,但是一旦我删除了对sys.databases的连接,只需要 9 秒。这段时间的大部分时间是 CPU 时间,几乎没有等待,没有阻塞,没有扫描,只有 13406 次逻辑读取和 1562 次 lob 读取。

所以我想知道的是,为什么加入 sys.databases导致巨大的性能下降?为什么不一致?

发生的情况是,当我运行以下测试查询时,有时会无缘无故地花费超过 8 分钟,而其他时间则在 11 秒内完成。

SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
SET NOCOUNT ON;
DECLARE @snapshot_timeoffset AS datetimeoffset(3) = CAST(SYSDATETIMEOFFSET() AS datetimeoffset(3));

SELECT
    @snapshot_timeoffset AS [snapshot_timeoffset]
    ,db.name AS [database_name]  
    ,OBJECT_SCHEMA_NAME(st.objectid, st.dbid) [schema_name] 
    ,OBJECT_NAME(st.objectid, st.dbid) [object_name]   
    ,cp.objtype
    ,cp.usecounts
    ,cp.refcounts
    -- find the offset of the actual statement being executed
    ,SUBSTRING(st.text, 
            CASE
                WHEN qs.statement_start_offset = 0 OR qs.statement_start_offset IS NULL THEN 1  
                ELSE qs.statement_start_offset/2 + 1
            END, 
            CASE 
                WHEN qs.statement_end_offset = 0 OR qs.statement_end_offset = -1 OR qs.statement_end_offset IS NULL THEN LEN(st.text)  
                ELSE qs.statement_end_offset/2 
            END - 
            CASE
                WHEN qs.statement_start_offset = 0 OR qs.statement_start_offset IS NULL THEN 1  
                ELSE qs.statement_start_offset/2
            END + 1 
        ) AS [statement]  
    ,qs.execution_count
    ,qs.total_logical_reads
    ,qs.last_logical_reads
    ,qs.min_logical_reads
    ,qs.max_logical_reads
    ,qs.total_logical_writes
    ,qs.last_logical_writes
    ,qs.min_logical_writes
    ,qs.max_logical_writes
    ,qs.total_physical_reads
    ,qs.last_physical_reads
    ,qs.min_physical_reads
    ,qs.max_physical_reads
    ,qs.total_worker_time
    ,qs.last_worker_time
    ,qs.min_worker_time
    ,qs.max_worker_time
    ,qs.total_clr_time
    ,qs.last_clr_time
    ,qs.min_clr_time
    ,qs.max_clr_time
    ,qs.total_elapsed_time
    ,qs.last_elapsed_time
    ,qs.min_elapsed_time
    ,qs.max_elapsed_time
    ,qs.total_rows
    ,qs.last_rows
    ,qs.min_rows
    ,qs.max_rows
    ,qs.last_execution_time
    ,qs.creation_time
    ,qs.sql_handle
    ,qs.plan_handle
    ,qs.statement_start_offset
    ,qs.statement_end_offset
INTO #QueryStats
FROM master.sys.dm_exec_query_stats qs   
INNER JOIN  master.sys.dm_exec_cached_plans cp 
ON qs.plan_handle = cp.plan_handle 
CROSS APPLY  master.sys.dm_exec_sql_text(qs.plan_handle) st 
INNER JOIN  master.sys.databases db
ON st.dbid = db.database_id;
Run Code Online (Sandbox Code Playgroud)

糟糕的计划

一个偶然的机会,我决定移除对sys.databases的内部连接,并用DB_NAME()函数替换数据库名称的查找,现在它在 9 秒内始终如一地运行:

SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
SET NOCOUNT ON;
DECLARE @snapshot_timeoffset AS datetimeoffset(3) = CAST(SYSDATETIMEOFFSET() AS datetimeoffset(3));

SELECT
    @snapshot_timeoffset AS [snapshot_timeoffset]
    ,DB_NAME(st.dbid) AS [database_name]  
    ,OBJECT_SCHEMA_NAME(st.objectid, st.dbid) [schema_name] 
    ,OBJECT_NAME(st.objectid, st.dbid) [object_name]   
    ,cp.objtype
    ,cp.usecounts
    ,cp.refcounts
    -- find the offset of the actual statement being executed
    ,SUBSTRING(st.text, 
            CASE
                WHEN qs.statement_start_offset = 0 OR qs.statement_start_offset IS NULL THEN 1  
                ELSE qs.statement_start_offset/2 + 1
            END, 
            CASE 
                WHEN qs.statement_end_offset = 0 OR qs.statement_end_offset = -1 OR qs.statement_end_offset IS NULL THEN LEN(st.text)  
                ELSE qs.statement_end_offset/2 
            END - 
            CASE
                WHEN qs.statement_start_offset = 0 OR qs.statement_start_offset IS NULL THEN 1  
                ELSE qs.statement_start_offset/2
            END + 1 
        ) AS [statement]  
    ,qs.execution_count
    ,qs.total_logical_reads
    ,qs.last_logical_reads
    ,qs.min_logical_reads
    ,qs.max_logical_reads
    ,qs.total_logical_writes
    ,qs.last_logical_writes
    ,qs.min_logical_writes
    ,qs.max_logical_writes
    ,qs.total_physical_reads
    ,qs.last_physical_reads
    ,qs.min_physical_reads
    ,qs.max_physical_reads
    ,qs.total_worker_time
    ,qs.last_worker_time
    ,qs.min_worker_time
    ,qs.max_worker_time
    ,qs.total_clr_time
    ,qs.last_clr_time
    ,qs.min_clr_time
    ,qs.max_clr_time
    ,qs.total_elapsed_time
    ,qs.last_elapsed_time
    ,qs.min_elapsed_time
    ,qs.max_elapsed_time
    ,qs.total_rows
    ,qs.last_rows
    ,qs.min_rows
    ,qs.max_rows
    ,qs.last_execution_time
    ,qs.creation_time
    ,qs.sql_handle
    ,qs.plan_handle
    ,qs.statement_start_offset
    ,qs.statement_end_offset
INTO #QueryStats
FROM master.sys.dm_exec_query_stats qs   
INNER JOIN  master.sys.dm_exec_cached_plans cp 
ON qs.plan_handle = cp.plan_handle 
CROSS APPLY  master.sys.dm_exec_sql_text(qs.plan_handle) st;
Run Code Online (Sandbox Code Playgroud)

在此处输入图片说明

注意:表值函数[SYSDMEXECCACHEDPLANS]在良好计划中具有估计的 CPU 成本 0.0522562、估计的行数 52256 和实际的行数 52251。但是在之前的计划中,相同的函数现在有 Actual Number of Rows 327605402,这是一个巨大的差异。

我运行了 Paul Randal 的扩展事件会话,它根据他的建议跟踪特定会话的等待类型,并得到以下输出:

SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
SET NOCOUNT ON;
DECLARE @snapshot_timeoffset AS datetimeoffset(3) = CAST(SYSDATETIMEOFFSET() AS datetimeoffset(3));

SELECT
    @snapshot_timeoffset AS [snapshot_timeoffset]
    ,db.name AS [database_name]  
    ,OBJECT_SCHEMA_NAME(st.objectid, st.dbid) [schema_name] 
    ,OBJECT_NAME(st.objectid, st.dbid) [object_name]   
    ,cp.objtype
    ,cp.usecounts
    ,cp.refcounts
    -- find the offset of the actual statement being executed
    ,SUBSTRING(st.text, 
            CASE
                WHEN qs.statement_start_offset = 0 OR qs.statement_start_offset IS NULL THEN 1  
                ELSE qs.statement_start_offset/2 + 1
            END, 
            CASE 
                WHEN qs.statement_end_offset = 0 OR qs.statement_end_offset = -1 OR qs.statement_end_offset IS NULL THEN LEN(st.text)  
                ELSE qs.statement_end_offset/2 
            END - 
            CASE
                WHEN qs.statement_start_offset = 0 OR qs.statement_start_offset IS NULL THEN 1  
                ELSE qs.statement_start_offset/2
            END + 1 
        ) AS [statement]  
    ,qs.execution_count
    ,qs.total_logical_reads
    ,qs.last_logical_reads
    ,qs.min_logical_reads
    ,qs.max_logical_reads
    ,qs.total_logical_writes
    ,qs.last_logical_writes
    ,qs.min_logical_writes
    ,qs.max_logical_writes
    ,qs.total_physical_reads
    ,qs.last_physical_reads
    ,qs.min_physical_reads
    ,qs.max_physical_reads
    ,qs.total_worker_time
    ,qs.last_worker_time
    ,qs.min_worker_time
    ,qs.max_worker_time
    ,qs.total_clr_time
    ,qs.last_clr_time
    ,qs.min_clr_time
    ,qs.max_clr_time
    ,qs.total_elapsed_time
    ,qs.last_elapsed_time
    ,qs.min_elapsed_time
    ,qs.max_elapsed_time
    ,qs.total_rows
    ,qs.last_rows
    ,qs.min_rows
    ,qs.max_rows
    ,qs.last_execution_time
    ,qs.creation_time
    ,qs.sql_handle
    ,qs.plan_handle
    ,qs.statement_start_offset
    ,qs.statement_end_offset
INTO #QueryStats
FROM master.sys.dm_exec_query_stats qs   
INNER JOIN  master.sys.dm_exec_cached_plans cp 
ON qs.plan_handle = cp.plan_handle 
CROSS APPLY  master.sys.dm_exec_sql_text(qs.plan_handle) st 
INNER JOIN  master.sys.databases db
ON st.dbid = db.database_id;
Run Code Online (Sandbox Code Playgroud)

请注意,等待时间很少,但 CPU 时间几乎与持续时间相匹配。Paul 提到这可能是自旋锁争用,但是我们在 SQL 2014 SP1 CU2 上运行并且错误https://support.microsoft.com/en-ca/kb/3026083已在 SP1 中修复。同样,在 system_health.xel 上看不到任何内容。

sys.databases本身的查询总是很快。

Pau*_*ite 10

...为什么加入 sys.databases 会导致巨大的性能下降?为什么不一致?

加入sys.databases没有什么特别之处。优化器碰巧选择了一个对第一次查询效率低下的计划。具体而言,在该计划领域:

计划片段

...优化器选择嵌套循环连接到SYSDMEXECCACHEDPLANS,大概是基于对连接的外部输入(来自合并连接)的极少量驱动行的期望。优化器引入了一个表假脱机来降低嵌套循环连接的外部输入上任何重复值的处理成本,但这不太可能非常有效 - 散列连接会“更好”。

..相同的函数现在有实际行数 327605402,这是一个巨大的差异。

这是在 SSMS 中读取执行计划时的常见错误(SQL Sentry 的计划资源管理器不会遇到此问题)。在 SSMS 中,嵌套循环连接内侧的估计行数显示在每次迭代中,而实际行数显示在所有迭代中。这是“有问题的设计决定”的结果

因此,性能不佳的根本原因很可能仅仅是所有缓存计划的完整集合被扫描的次数比优化器预期的要多。扫描整个缓存6269 次会很慢(除非当时缓存很小)。

基数估计错误不仅仅发生在用户表中,因此这没什么好奇怪的。不要专门将其归咎于sys.databases。“额外的连接”或“对谓词的轻微更改”对计划选择产生巨大影响是很常见的。

您有比平时更少的选项来帮助优化器查询系统表、视图和函数。对于专家分析师,提示可能是合适的解决方案。在其他情况下,最好将查询分解为多个步骤。在您的情况下,根据提供的信息,简单地用元数据功能替换“额外连接”似乎就足够了。


小智 8

SOS_SCHEDULER_YIELD 累积就像我在#sqlhelp 上建议的那样。每个都相当于查询的 4 毫秒 CPU 时间,并且它们始终显示零资源等待时间,因为不涉及资源等待(线程让出处理器并直接进入调度程序上的可运行队列的底部)。

所以 - 这个查询是通过 CPU 搅动的,不需要任何其他资源。

这也与自旋锁无关,因为它们不会显示为特定的等待类型(SOS_SCHEDULER_YIELD = 自旋锁的常见误解)。当你说没有任何等待时,我建议。

当它运行缓慢时,它返回的行是否比快速运行时明显多?