Open nereuschen opened 9 years ago
让应届生童鞋做了一个批量修改业务数据的工具,目的是代替人工通过系统重复处理这些业务数据。工具的输入是业务模型id,然后根据约定的业务逻辑处理这些数据。当在批量一次性提交5000条id执行后,出现了一系列异常现象。
SQL QPS飙高
SQL QPS从100飙到700,涨了6倍
处理时间过长,响应时间高于平时一个数量级
处理5000条业务数据耗时20min,QPS是4(=5000条/(20min*60s)),处理一条数据的响应时间是250ms(=1000ms/4),但日常人工处理1条数据的响应时间是30ms,大致相差10倍。
页面显示504 Gateway Time-out
说明NG处理超时了
出了问题,首先应该看日志
Tomcat日志
主要查看biz.log和access.log,记业务日志和tomcat的http请求日志
biz.log
代码执行过程中,记录了处理失败的业务数据Id;grep 日志信息发现这个集群中的每个tomcat实例的业务日志中都出现了部分相同的业务数据Id。让该童鞋merge了一下日志文件,给出的结论是Id的记录总数超过1W。1W 这数据明细不对,不可能大于输入的Id数5000才对。看了一下去重的shell使用不当导致,正确统计后是2900+。
[xxxxx~0][xxx:24:03.396][INFO][xxxImpl:117] 执行到id=XXX [xxxxx~0][xxx:25:03.443][INFO][xxxImpl:117] 执行到id=XXX [xxxxx~0][xxx:26:03.340][INFO][xxxImpl:117] 执行到id=XXX [xxxxx~0][xxx:27:03.363][INFO][xxxImpl:117] 执行到id=XXX
access.log
grep POST的URL后,发现在集群环境中每个Tomcat实例的access.log中都有这个URL。
[xxx:17:38:55 +0800] "POST /xxx/batch/update HTTP/1.0" 200 65493 "http://xxx/api/batch/update/rules" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36" "-" [xxx:17:39:53 +0800] "POST /xxx/batch/update HTTP/1.0" 200 65493 "http://xxx/api/batch/update/rules" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36" "-" [xxx:17:40:20 +0800] "POST /xxx/batch/update HTTP/1.0" 200 65493 "http://xxx/api/batch/update/rules" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36" "-" 192.168.114.144 [xxx:17:42:02 +0800] "POST /xxx/batch/update HTTP/1.0" 200 65493 "http://xxx/api/batch/update/rules" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36" "-" 192.168.114.144
从日志上看,请求都提交到集群中每个Tomcat实例上,只是相差60S而已
Nginx日志
有无无查看NG的权限,日后再补上
NG配置代码
通过日志不难发现请求被NG依次做了转发,导致每个tomcat实例都执行了1次
导致NG超时的根本原因是请求处理时间过长,超时导致,因此以下是比较常见的应用场景
方案2 杜绝超时的请求再次被转发
修改NG配置文件,在发生timeout时,勿将请求再次转发到机器中的其他的节点
方案3 请求异步化
将响应时间长(>60s)的请求异步化,请求提交后,通过后台task去执行
http://www.nginxtips.com/504-gateway-time-out-using-nginx/ http://wiki.nginx.org/HttpProxyModule#proxy_connect_timeout http://saiyaren.iteye.com/blog/1914865
缘起
让应届生童鞋做了一个批量修改业务数据的工具,目的是代替人工通过系统重复处理这些业务数据。工具的输入是业务模型id,然后根据约定的业务逻辑处理这些数据。当在批量一次性提交5000条id执行后,出现了一系列异常现象。
现象
SQL QPS飙高
SQL QPS从100飙到700,涨了6倍
处理时间过长,响应时间高于平时一个数量级
处理5000条业务数据耗时20min,QPS是4(=5000条/(20min*60s)),处理一条数据的响应时间是250ms(=1000ms/4),但日常人工处理1条数据的响应时间是30ms,大致相差10倍。
页面显示504 Gateway Time-out
说明NG处理超时了
问题剖析
出了问题,首先应该看日志
Tomcat日志
主要查看biz.log和access.log,记业务日志和tomcat的http请求日志
biz.log
代码执行过程中,记录了处理失败的业务数据Id;grep 日志信息发现这个集群中的每个tomcat实例的业务日志中都出现了部分相同的业务数据Id。让该童鞋merge了一下日志文件,给出的结论是Id的记录总数超过1W。1W 这数据明细不对,不可能大于输入的Id数5000才对。看了一下去重的shell使用不当导致,正确统计后是2900+。
access.log
grep POST的URL后,发现在集群环境中每个Tomcat实例的access.log中都有这个URL。
从日志上看,请求都提交到集群中每个Tomcat实例上,只是相差60S而已
Nginx日志
有无无查看NG的权限,日后再补上
通过日志不难发现请求被NG依次做了转发,导致每个tomcat实例都执行了1次
常见场景
导致NG超时的根本原因是请求处理时间过长,超时导致,因此以下是比较常见的应用场景
解决方案
方案2 杜绝超时的请求再次被转发
修改NG配置文件,在发生timeout时,勿将请求再次转发到机器中的其他的节点
方案3 请求异步化
将响应时间长(>60s)的请求异步化,请求提交后,通过后台task去执行
http://www.nginxtips.com/504-gateway-time-out-using-nginx/ http://wiki.nginx.org/HttpProxyModule#proxy_connect_timeout http://saiyaren.iteye.com/blog/1914865