只读副本上的长时间运行查询，在主副本上需要一些时间

Question

只读副本上的长时间运行查询，在主副本上需要一些时间

Joh*_*ner 9 performance sql-server availability-groups sql-server-2017 query-performance

我有一个 4 节点 AG 设置，如下所示：

所有节点的VM硬件配置：

Microsoft SQL Server 2017 企业版 (RTM-CU14) (KB4484710)
16 个 vCPU
356 GB RAM（这个故事很长……）
最大并行度：1（根据应用程序供应商的要求）
并行性的成本阈值：50
最大服务器内存 (MB)：338944 (331 GB)

AG配置：

节点 1：主节点或同步提交非可读辅助节点，配置为自动故障转移
节点 2：主节点或同步提交非可读辅助节点，配置为自动故障转移
节点 3：具有异步提交的可读辅助集，配置为手动故障转移
节点 4：具有异步提交的可读辅助集，配置为手动故障转移

有问题的查询：

这个查询没有什么特别疯狂的地方，它提供了应用程序内各个队列中未完成工作项的摘要。您可以从下面的执行计划链接之一中查看代码。

主节点上的执行行为：

在 Primary 节点上执行时，执行时间一般在 1 秒左右。这是执行计划，以下是从主节点的 STATISTICS IO 和 STATISTICS TIME 捕获的统计信息：

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

 SQL Server Execution Times:
   CPU time = 500 ms,  elapsed time = 656 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

Run Code Online (Sandbox Code Playgroud)

只读辅助节点上的执行行为：

在只读辅助节点（即节点 3 或节点 4）上执行时，此查询使用相同的执行计划（这是一个不同的计划链接）并显示大致相同的执行统计信息（例如，可能会有更多页面扫描，因为这些结果总是在变化），但除了 CPU 时间外，它们看起来非常相似。以下是从只读辅助节点的 STATISTICS IO 和 STATISTICS TIME 捕获的统计信息：

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

 SQL Server Execution Times:
   CPU time = 55719 ms,  elapsed time = 56335 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

Run Code Online (Sandbox Code Playgroud)

其他详情：

在执行此查询时，我还在辅助服务器上运行了Paul Randal sp_WhoIsActive和Paul Randal 的WaitingTasks.sql脚本，但我没有看到任何等待发生，坦率地说，这令人沮丧：

这看起来也不是 AG 延迟的情况，因为同步状态实际上非常好：

--https://sqlperformance.com/2015/08/monitoring/availability-group-replica-sync

SELECT 
       ar.replica_server_name, 
       adc.database_name, 
       ag.name AS ag_name, 
       drs.is_local, 
       drs.synchronization_state_desc, 
       drs.synchronization_health_desc, 
       --drs.last_hardened_lsn, 
       --drs.last_hardened_time, 
       drs.last_redone_time, 
       drs.redo_queue_size, 
       drs.redo_rate, 
       (drs.redo_queue_size / drs.redo_rate) / 60.0 AS est_redo_completion_time_min,
       drs.last_commit_lsn, 
       drs.last_commit_time
FROM sys.dm_hadr_database_replica_states AS drs
INNER JOIN sys.availability_databases_cluster AS adc 
       ON drs.group_id = adc.group_id AND 
       drs.group_database_id = adc.group_database_id
INNER JOIN sys.availability_groups AS ag
       ON ag.group_id = drs.group_id
INNER JOIN sys.availability_replicas AS ar 
       ON drs.group_id = ar.group_id AND 
       drs.replica_id = ar.replica_id
ORDER BY 
       ag.name, 
       ar.replica_server_name, 
       adc.database_name;

Run Code Online (Sandbox Code Playgroud)

这个查询似乎是最严重的冒犯者。其他在主节点上也需要亚秒时间的查询在辅助节点上可能需要 1 到 5 秒，虽然行为没有那么严重，但看起来确实会导致问题。

最后，我还查看了服务器并检查了外部进程，例如 A/V 扫描、生成意外 I/O 的外部作业等，但结果却一无所获。我不认为这是由 SQL Server 进程之外的任何事情引起的。

问题：

我现在才中午，这已经是漫长的一天了，所以我怀疑我在这里遗漏了一些明显的东西。要么是这样，要么是我们配置错误，这是可能的，因为我们已经多次调用与此环境相关的供应商和 MS。

对于我的所有调查，我似乎无法找到导致这种性能差异的原因。我希望在辅助节点上看到某种等待，但什么也没有。如何进一步解决此问题以找出根本原因？有没有人以前见过这种行为并找到解决方法？

更新 #1 在将第三个节点（只读副本之一）的状态交换为不可读，然后作为测试返回可读后，该副本仍然被一个开放事务保留，任何客户端查询都显示HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONING等待。

运行DBCC OPENTRAN命令会产生以下结果：

Oldest active transaction:
    SPID (server process ID): 420s
    UID (user ID) : -1
    Name          : QDS nested transaction
    LSN           : (941189:33148:8)
    Start time    : May  7 2019 12:54:06:753PM
    SID           : 0x0
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

Run Code Online (Sandbox Code Playgroud)

在中查找此 SPID 时sp_who2，它会将其显示为一个BACKGROUND进程，并QUERY STORE BACK作为命令列出。

虽然我们都能够采取的TLog备份，我想我们正在运行到的类似的功能这个解决的错误，所以我打算与MS关于这一具体问题今天开了罚单。

根据该票的结果，我将尝试根据 Joe 的建议捕获调用堆栈跟踪，然后看看我们会去哪里。

最终更新（问题自行解决）

在超过查询存储事务打开的 52 小时标记（如上所述）之后，AG 决定自动进行故障转移。在这发生之前，我确实提取了一些额外的指标。根据Sean 提供的这个链接，有问题的数据库有一个非常大的版本存储专用于该数据库，特别是在某一时刻，我在该reserved_page_count字段中记录了 1651360 页，并记录了 13210880 页的reserved_space_kb值。

每ERRORLOGs，故障转移与交易相关的硬化失败5分钟后，洪水发生QDS base transaction和QDS nested transaction交易。

在我的案例中，故障转移确实导致了大约 10 分钟的中断。数据库大小约为 6TB 并且非常活跃，所以在我看来这实际上非常好。当新的主节点在此期间在线时，没有客户端查询可以完成，因为它们都在等待QDS_LOADDB等待类型。

故障转移后，版本存储编号减少到 176 个 forreserved_page_count和 1408 个 for reserved_space_kb。对辅助只读副本的查询也开始像从主副本运行一样快地执行，因此看起来由于故障转移，行为完全消失了。

Answer 1

Joe*_*ish 10

免责声明：我对可用性组一无所知，但我确实知道一些关于对似乎使用更多 CPU 的查询进行故障排除的知识。

您有 CPU 问题，因为您使用了过多的 CPU。关于等待要说的一件重要事情是几乎所有等待都不是 CPU 忙的。当一个 worker 进入等待状态时，它已经让步并且不再在 SQLOS 中的调度程序上运行。因此，如果您有一个包含以下运行统计信息的 MAXDOP 1 查询：

CPU 时间 = 55719 毫秒，已用时间 = 56335 毫秒。

查询的 CPU 利用率几乎达到了 99%。为什么要为该查询提供有意义的等待统计信息？如果您有一些 CPU 忙等待（例如外部等待或抢占等待），您可能会看到一些，但这也不能保证。最重要的是，等待统计在这里可能没有那么有用。

有一些事情要按粗略的顺序检查（顺序取决于您对环境的了解）：

辅助服务器是否正在进行任何昂贵的监控，例如扩展事件、跟踪或分析？
辅助服务器的硬件是否与主服务器大致匹配？
辅助服务器是否存在任何配置或软件问题？
任何重要的等待或闩锁？可能不适用于您的查询，但仍可能提供线索。
任何重要的自旋锁？
是否有其他 DMV 或您可以在 SQL Server 中检查的可能提供线索的内容？您提到可用性组可能是问题的关键部分。
ETW 追踪告诉你什么？
你们有什么样的支持协议？

以上大部分内容都很好地涵盖了各种博客文章和文档，但我将扩展 ETW 跟踪。如果您想知道为什么 SQL Server 为特定查询使用如此多的 CPU 并且您可以访问主机，您可以随时执行 ETW 跟踪以查看调用堆栈并查看各种调用堆栈正在执行多少 CPU。换句话说，如果您知道如何提问，主机操作系统很乐意告诉您 CPU 的用途。进行 ETW 跟踪的常用方法包括Windows Performance Recorder和PerfView。

理解这些结果需要深入的内部知识，而且很容易得出错误的结论。在许多情况下，最好收集原始数据并请专家查看。执行跟踪时，您希望在 SQL Server 中进行的活动尽可能少。以下是此处发布的一些使用 ETW 跟踪得出有关 SQL Server 的结论的答案：

我怀疑在您的情况下，如果您能够在 45 秒查询运行时收集调用堆栈，您将获得一些关于问题性质的非常有用的线索。

Answer 2

Sea*_*ser 10

这个答案是 Joe 的答案的补充，因为我不能 100% 确定它是版本存储，但是到目前为止有足够的证据暗示这是问题的一部分。

当辅助副本被标记为可读时，需要首先获得版本信息的良好稳定状态，以便辅助副本上的所有读取操作都有一个已知且良好的起点。当它正在等待转换并且主节点上仍有打开的事务时，这将表现为HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONING并且也是一个很好的指标，表明主节点确实经历了相当多的数据流失（或者至少有人有一个非常长的打开事务也不好）。事务打开的时间越长，数据更改越多，发生的版本控制就越多。

次要副本通过在会话的幕后使用快照隔离来实现可读状态，即使您检查会话信息，您也会看到它显示在默认的读取提交中。由于快照隔离是乐观的并且使用版本存储，因此所有更改都需要进行版本控制。当辅助节点上有许多正在运行（并且可能长时间运行）的查询而主节点上的数据流失率很高时，这种情况会加剧。通常，这仅体现在 OLTP 系统的几个表中，但它完全取决于应用程序和工作负载。

版本存储本身以代为单位进行测量，当运行需要使用版本存储的查询时，版本控制记录指针用于指向该行的 TempDB 链。我说链，因为它是该行的版本列表，整个链必须按顺序遍历以根据事务的开始时间戳找到正确的版本，以便结果与给定时间的数据一致。

如果由于主副本和辅助副本上的长时间运行事务，这些行的版本存储有很多代，这将导致查询运行时间比平均时间长，并且通常以更高的 CPU 的形式出现，而所有其他项目似乎保持完全相同- 如执行计划、统计、返回行等。链的行走几乎是纯粹的cpu操作，所以当链变得很长，返回的行数很高时，你得到一个（不是线性的，但是可以关闭）增加查询时间。

唯一可以做的就是限制主节点和辅助节点上的事务长度，以确保版本存储在 TempDB 中不会变得太大而具有多代。尝试清理版本存储大约每分钟发生一次，但是清理要求在删除之前不再需要来自同一代的所有版本，并且在不再需要最旧的版本之前不能清理所有未来版本。因此，长时间运行的查询会导致无法有效清理许多未使用的代。

切换副本进入和退出可读模式也将清除版本存储，因为它不再可读。

还有其他项目也可能在起作用，但考虑到当前数据和复制品的反应方式，这似乎是最合理的。

TempDB 版本控制 DMV（不要与 ADR 版本控制混淆）。

Answer 3

Joh*_*ner 5

由于问题自行解决，我只能推测其原因（押韵并非故意）。根据 Sean 的帖子以及开放的查询存储事务看起来是我增加版本存储大小的根本原因（例如HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONING等待的原因）这一事实，我只能假设查询存储参与了提出了。这个数据库更大（~6TB），非常活跃，而且绝大多数查询它是在客户端生成的，而不是参数化的（即即席查询），所以我不相信查询存储有助于提供在这种情况下有很多用途。因此，我们将在未来的维护窗口期间禁用此环境中的查询存储，之后我怀疑我们不会再看到这种行为。

我们确实与 Microsoft 开了一张票，但时间对我们不利，因为在我们可以通过 PSSDIAG 跟踪或类似方法进行任何详细分析之前，问题已得到解决。我希望他们能够进行一些本地化测试并复制此问题，以防这是我们遇到的错误。如果确定了有关更永久解决方案的任何进一步更新，我也一定会更新此答案。

归档时间：	6 年，4 月前
查看次数：	1433 次
最近记录：	6 年，4 月前