主页 / dba / 问题 / 244068
Accepted
Ian Boyd
Asked: 2019-07-30 10:48:55 +0800 CST

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

  • 772

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

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

存储过程的执行时间差别很大。此存储过程的许多执行都在 < 1 秒内返回：

在此处输入图像描述

而对于那个“快速”的存储桶来说，它远远小于 1 秒。实际上大约是 90 毫秒：

在此处输入图像描述

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

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

寻找因果关系的相关性

所以我试图关联：

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

似乎没有任何相关性。似乎没有一个原因

  • 持续时间与逻辑读取：无论是少量还是大量逻辑读取，持续时间仍然波动很大：

    在此处输入图像描述

  • 持续时间与物理读取：即使查询不是从缓存中提供的，并且需要大量物理读取，它也不会影响持续时间：

    在此处输入图像描述

  • duration vs cpu time：无论查询占用了 0 秒的 CPU 时间，还是完整的 2.5 秒的 CPU 时间，持续时间都具有相同的可变性：

    在此处输入图像描述

奖励：我注意到Duration v Physical Reads和Duration v CPU time看起来非常相似。如果我尝试将 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

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

缓慢的计划

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

  • `EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04:00:00.000', @EndDate = '20190726 04:00:00.000'
  • `EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04:00:00.000', @EndDate = '20190726 04:00:00.000'

The same stored procedure, with the same parameters, run back to back:

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

Call 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

Call 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

It makes sense for the plans to be identical; it's executing the same stored procedure, with the same parameters.

sql-server sql-server-2012

1 个回答

  1. Best Answer

    Have a look at the wait_stats and it will show what the biggest bottlenecks are on your SQL server.

    I recently experienced a problem where an external application was intermittently slow. Running stored procedures on the server itself was always fast though.

    Performance monitoring showed nothing to be concerned about at all with SQL Caches or the RAM usage and IO on the server.

    What helped narrow down the investigation was querying the wait stats that are collected by SQL in 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);

    上述查询和更多详细信息来自MSSQLTips 网站。

    sp_BlitzFirstBrent Ozar网站上的脚本还将向您展示导致减速的原因。

    • 2

相关问题