【故障公告】SQL语句执行超时引发网站首页访问故障
非常抱歉,今天早上 6:37~8:15 期间,由于获取网站首页博文列表的 SQL 语句出现突发的查询超时问题,造成访问网站首页时出现 500 错误,由此给您带来麻烦,请您谅解。
故障的情况是这样的。
故障期间日志中记录了大量下面的错误。
2020-02-03 06:37:24.635 [Error] An unhandled exception has occurred while executing the request. / Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware System.Data.SqlClient.SqlException (0x80131904): Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (258): Unknown error 258 at System.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__126_0(Task`1 result)
数据库服务器(阿里云 RDS SQL Server 2016 实例)的 CPU 消耗突增。
数据库服务器的 IOPS 暴增。
通过阿里云 RDS 控制台的 CloudDBA 可以查看到故障期间获取首页博文的 SQL 语句被执行了3万多次,执行这么多次是由于查询超时,无法建立缓存,每次请求都要访问数据库。
发现故障后,我们通过阿里云 RDS 的主备切换恢复了正常。
经过对故障的排查分析,锁定的最大嫌疑对象是 SQL Server 参数嗅探(详见园子里的博文 什么是 SQL Server 参数嗅探)。
对于这种因为重用他人生成的执行计划而导致的水土不服现象,SQL Server 有一个专有名词,叫“参数嗅探 parameter sniffing”。
而且我们找到了引发 SQL Server 参数嗅探问题的条件。
在我们的 open api 中提供了获取首页博文列表的 web api ,但没有限制可以获取的最大博文数,也就是下面的 ItemCount 参数(除了 open api ,其他地方调用时 ItemCount 值都是 20 )。
SELECT TOP (@ItemCount)
假如有人调用 open api 时给 ItemCount 传了一个很大的值,比如 20000 ,虽然调用的是同样的 SQL 语句,但由于 ItemCount 的值不同, SQL Server 可能会生成相差很大的执行计划,对于 ItemCount 20000 性能比较好的执行计划,对于 ItemCount 20 可能性能极差。如果查询 ItemCount 20000 时生成的执行计划被缓存下来,查询 ItemCount 20 时继续使用这个执行计划,就会出现本来好好的 SQL 查询突然变得性能极差。我们今天遇到的故障很可能就是这个原因,而且故障时就一个 SQL 语句出现问题(正好就这个 SQL 查询缓存了水土不服的执行计划),其他都正常,也验证了这个猜测。
通过这次故障,我们吸取的教训是一定要在代码中对 ItemCount 与 PageSize 的最大值进行限制,它不仅仅是带来不必要的低性能查询,而且可能会因为 SQL Server 参数嗅探问题拖垮整个数据库。