主页 / dba / 问题 / 237671
Accepted
John Eisbrener
Asked: 2019-05-09 09:12:12 +0800 CST

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

  • 772

我有一个 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.

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

在任一只读辅助节点（即节点 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.

其他详情：

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

在此处输入图像描述

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

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

在此处输入图像描述

这个查询似乎是最严重的违规者。在主节点上也需要亚秒级时间的其他查询在辅助节点上可能需要 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.

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

虽然我们能够进行 TLog 备份，但我怀疑我们遇到了这个已解决错误的类似功能，所以我计划今天就这个特定问题向 MS 开一张票。

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

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

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

QDS base transaction根据错误日志，故障转移是在与事务相关的事务强化失败 5 分钟后发生的QDS nested transaction。

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

故障转移后，版本存储数量减少到 176reserved_page_count和 1408 reserved_space_kb。对辅助只读副本的查询也开始像从主副本运行一样快地执行，因此看起来该行为完全消失了，这是故障转移的结果。

sql-server performance

3 个回答

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

    你有一个CPU问题，因为你使用了太多。关于等待要说的一件重要的事情是几乎所有的等待都不是 CPU 忙。当工作人员进入等待状态时，它已经屈服并且不再在 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 秒查询运行时收集调用堆栈，您将获得一些关于问题性质的非常有用的线索。

    • 10
  2. Best Answer

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

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

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

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

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

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

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

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

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

    • 10

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

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

    • 5

相关问题