这是服务器过载的症状吗？

Question

这是服务器过载的症状吗？

Ian*_*oyd 12 sql-server sql-server-2012

我一直在尝试诊断应用程序中的减速。为此，我记录了 SQL Server扩展事件。

对于这个问题，我正在研究一个特定的存储过程。
但是有一组核心的十几个存储过程同样可以用作一对一的调查
每当我手动运行其中一个存储过程时，它总是运行得很快
如果用户再次尝试：它会运行得很快。

存储过程的执行时间变化很大。这个存储过程的很多执行在 < 1s 内返回：

而对于那个“快速”的bucket，它的时间远小于1s。它实际上是大约 90 毫秒：

但是有一个长尾用户必须等待 2s、3s、4s 秒。有些必须等待 12 秒、13 秒、14 秒。然后是真正可怜的灵魂，他们必须等待 22 秒、23 秒、24 秒。

30 秒后，客户端应用程序放弃，中止查询，用户不得不等待30 秒。

寻找因果关系的相关性

所以我试图关联：

持续时间与逻辑读取
持续时间 vs物理读取
持续时间与CPU 时间

而且似乎没有任何相关性；似乎没有一个原因

持续时间 vs 逻辑读取：无论是少量还是大量的逻辑读取，持续时间仍然波动很大：
持续时间 vs 物理读取：即使查询不是从缓存中提供的，并且需要大量物理读取，它也不会影响持续时间：
持续时间 vs cpu 时间：无论查询占用 0 秒的 CPU 时间，还是完整的 2.5 秒的 CPU 时间，持续时间都具有相同的可变性：

奖励：我注意到Duration v Physical Reads和Duration v CPU 时间看起来非常相似。如果我尝试将 CPU 时间与物理读取相关联，就会证明这一点：

事实证明，大量 CPU 使用来自 I/O。谁知道！

因此，如果执行查询的行为无法解释执行时间的差异，是否意味着它与 CPU 或硬盘驱动器无关？

如果 CPU 或硬盘驱动器是瓶颈；不会是瓶颈吧？

如果我们假设瓶颈是 CPU；该服务器的 CPU 供电不足：

那么使用更多 CPU 时间的执行会不会花费更长的时间？
因为他们必须使用过载的 CPU 与其他人一起完成？

硬盘驱动器也是如此。如果我们假设硬盘是一个瓶颈；硬盘驱动器没有足够的随机吞吐量用于此服务器：

那么使用更多物理读取的执行会不会花费更长的时间？
因为他们必须与其他人一起使用过载的硬盘驱动器 I/O 来完成？

存储过程本身既不执行也不要求任何写入。

通常它返回 0 行 (90%)。
有时它会返回 1 行 (7%)。
很少会返回 2 行 (1.4%)。
在最坏的情况下，它返回了超过 2 行（一次返回 12 行）

所以它不像是在返回大量的数据。

服务器 CPU 使用率

服务器的处理器使用率平均约为 1.8%，偶尔会高达 18% - 因此 CPU 负载似乎不是问题：

所以服务器 CPU 似乎没有过载。

但是服务器是虚拟的...

宇宙之外的东西？

我能想象的唯一剩下的就是存在于服务器宇宙之外的东西。

如果不是逻辑读取
这不是物理读取
这不是 CPU 使用率
这不是 CPU 负载

它不像是存储过程的参数（因为手动发出相同的查询并且不需要 27 秒 - 需要大约 0 秒）。

还有什么可以解释服务器有时需要 30 秒而不是 0 秒来运行相同的编译存储过程。

检查站？

这是一个虚拟服务器

主机超载？
同一主机上的另一个虚拟机？

浏览服务器的扩展事件；当查询突然需要 20 秒时，没有其他特别的事情发生。它运行良好，然后决定不正常运行：

2 秒
1秒
30秒
3 秒
2 秒

而且我找不到其他特别费劲的东西。它不是在每 2 小时事务日志备份期间。

还有什么会是什么？

除了“服务器”之外，我还有什么可以说的吗？

编辑：按时间关联

我意识到我已经将持续时间与所有内容相关联：

逻辑读
物理读取
CPU使用率

但我没有将它与一天中的时间相关联的一件事。也许每 2 小时的事务日志备份是一个问题。

或者也许在检查站期间卡盘确实发生了减速？

不：

英特尔至强金牌四核 6142。

编辑 - 人们正在假设查询执行计划

人们假设查询执行计划必须在“快”和“慢”之间有所不同。他们不是。

我们可以从检查中立即看到这一点。

我们知道更长的问题持续时间不是因为“糟糕”的执行计划：

一个需要更多逻辑读取的
一种从更多的连接和键查找中消耗更多 CPU

因为如果读取的增加或 CPU 的增加是查询持续时间增加的原因，那么我们在上面已经看到了。没有相关性。

但是让我们尝试将持续时间与 CPU 读取区域产品指标相关联：

相关性变得更小——这是一个悖论。

编辑：更新散点图以解决 Excel 散点图中具有大量值的错误。

下一步

我接下来的步骤是让某人必须为被阻止的查询生成事件- 5 秒后：

EXEC sp_configure 'blocked process threshold', '5';
RECONFIGURE

Run Code Online (Sandbox Code Playgroud)

它不会解释查询是否被阻止了4秒。但也许任何阻止查询 5 秒的东西也会阻止一些 4 秒。

缓慢的计划

这是正在执行的两个存储过程的慢速计划：

`执行 FindFrob @CustomerID = 7383，@StartDate = '20190725 04:00:00.000'，@EndDate = '20190726 04:00:00.000'
`执行 FindFrob @CustomerID = 7383，@StartDate = '20190725 04:00:00.000'，@EndDate = '20190726 04:00:00.000'

相同的存储过程，具有相同的参数，背靠背运行：

| Duration (us) | CPU time (us) | Logical reads | Physical reads | 
|---------------|---------------|---------------|----------------|
|    13,984,446 |        47,000 |         5,110 |            771 |
|     4,603,566 |        47,000 |         5,126 |            740 |

Run Code Online (Sandbox Code Playgroud)

呼叫 1：

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

Run Code Online (Sandbox Code Playgroud)

呼叫 2

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

Run Code Online (Sandbox Code Playgroud)

计划相同是有道理的；它使用相同的参数执行相同的存储过程。

Answer 1

小智 2

查看 wait_stats，它将显示 SQL 服务器上最大的瓶颈是什么。

我最近遇到一个问题，外部应用程序间歇性缓慢。不过，在服务器本身上运行存储过程总是很快。

性能监控表明，服务器上的 SQL 缓存或 RAM 使用情况和 IO 根本不需要担心。

有助于缩小调查范围的是查询 SQL 收集的等待统计信息sys.dm_os_wait_stats

SQLSkills 网站上的优秀脚本将向您展示您最常遇到的脚本。然后您可以缩小搜索范围以确定原因。

一旦您知道什么等待是大问题，此脚本将帮助缩小正在经历等待的会话/数据库的范围：

SELECT OSW.session_id,
       OSW.wait_duration_ms,
       OSW.wait_type,
       DB_NAME(EXR.database_id) AS DatabaseName
FROM sys.dm_os_waiting_tasks OSW
INNER JOIN sys.dm_exec_sessions EXS ON OSW.session_id = EXS.session_id
INNER JOIN sys.dm_exec_requests EXR ON EXR.session_id = OSW.session_id
OPTION(Recompile);

Run Code Online (Sandbox Code Playgroud)

上述查询和进一步的详细信息来自MSSQLTips 网站。

sp_BlitzFirstBrent Ozar网站上的脚本也会向您显示导致速度变慢的原因。

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