JMeter 50用户压测部分线程返回500错误（SQL超时）如何解决

问题本质定位 #

从返回的报错信息可直接判定，该错误为服务端数据库执行超时，和JMeter压测脚本无关：低并发（1-10用户）下数据库负载低可正常处理请求，并发提升至50用户时数据库处理能力达到瓶颈，触发SQL超时抛出异常。

报错核心特征：
异常类型为System.Data.SqlClient.SqlException，超时发生在订单确认服务的CommerceEngine.BLL.Services.Orders.ConfirmService.ProcessPayment方法第221行的数据库操作环节。

报错原始JSON #

{"Message":"An error has occurred.","ExceptionMessage":"Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.\r\nThe statement has been terminated.","ExceptionType":"System.Data.SqlClient.SqlException","StackTrace":"   at CommerceEngine.BLL.Services.Orders.ConfirmService.ProcessPayment(List`1 carts, OrderConfigurationModel orderConfig) in C:\\CookieDelivery_OnlineOrdering\\CookieDelivery_CommerceEngine\\BLL\\Services\\Orders\\ConfirmService.cs:line 221\r\n   at CookieService.Business.OrderBusiness.Place(OrderModel orderModel) in C:\\CookieDelivery_OnlineOrdering\\CookieService\\Business\\OrderBusiness.cs:line 460\r\n   at CookieService.Controllers.OrderController.Place(ValidationResultModel`1 order) in C:\CookieDelivery_OnlineOrdering\CookieService\Controllers\OrderController.cs:line 125\r\n   at lambda_method(Closure , Object , Object[] )\r\n   at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ActionExecutor.<>c__DisplayClass10.b__9(Object instance, Object[] methodParameters)\r\n   at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ExecuteAsync(HttpControllerContext controllerContext, IDictionary`2 arguments, CancellationToken cancellationToken)\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   at System.Web.Http.Controllers.ApiControllerActionInvoker.d__0.MoveNext()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   at System.Web.Http.Controllers.ActionFilterResult.d__2.MoveNext()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   at System.Web.Http.Filters.AuthorizationFilterAttribute.d__2.MoveNext()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   at System.Web.Http.Controllers.ExceptionFilterResult.d__0.MoveNext()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n   at System.Web.Http.Controllers.ExceptionFilterResult.d__0.MoveNext()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()\r\n   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   at System.Web.Http.Dispatcher.HttpControllerDispatcher.d__1.MoveNext()","InnerException":{"Message":"An error has occurred.","ExceptionMessage":"The wait operation timed out","ExceptionType":"System.ComponentModel.Win32Exception","StackTrace":null}}

响应头原始信息 #

HTTP/1.1 500 Internal Server Error
Cache-Control: no-cache
Pragma: no-cache
Content-Length: 3454
Content-Type: application/json; charset=utf-8
Expires: -1
Server: Microsoft-IIS/10.0
X-AspNet-Version: 4.0.30319
Request-Context: appId=cid-v1:0940d14d-c861-4eac-a08b-9d4139693e70
Access-Control-Expose-Headers: Request-Context
X-Powered-By: ASP.NET
Access-Control-Allow-Methods: POST, PUT, DELETE, GET, OPTIONS
Date: Wed, 10 Nov 2021 17:35:55 GMT

排查步骤 #

• 数据库层面排查
  1. 开启SQL Server慢查询日志，压测时捕获执行时间超过1s的SQL语句，定位ProcessPayment方法对应的数据库操作，检查是否存在未加索引的关联查询、大范围锁表的写入逻辑
  2. 查看压测时数据库锁等待队列，重点检查订单、购物车、支付相关表的锁粒度，确认是否存在行锁升级为表锁、长事务阻塞其他写入请求的情况
  3. 核对应用服务的数据库连接池配置，确认连接数上限是否低于50，导致并发请求拿不到连接排队超时
• 应用层面排查
  1. 检查下单接口的SQL命令超时时间配置，确认是否为默认30s，高并发下请求排队超过阈值被主动中断
  2. 梳理ProcessPayment方法逻辑，确认是否存在重复查询数据库、事务块包含非必要IO操作（如调用第三方接口时仍持有数据库事务锁）的问题
• 压测侧验证
  调整JMeter的Ramp-Up时间，将50用户的启动时长拉长到10-20s，若超时请求数量明显减少，可直接验证是瞬时并发超过数据库处理能力导致的问题

解决方案 #

• 数据库优化：给慢查询涉及的字段添加对应索引，拆分大事务为多个小事务减少锁持有时间，热点数据可引入Redis等缓存层降低数据库查询压力
• 应用优化：调整数据库连接池上限到合理值，将非数据库操作移出事务块，新增接口限流熔断机制，超过数据库处理能力的请求先排队或返回友好提示
• 配置调整：结合业务场景适当调高SQL命令超时时间，注意不要设置过高避免大量慢请求拖垮整个数据库服务

内容的提问来源于stack exchange，提问作者Teddyman