引入:
当我们做的某支付系统,以一组web service的方式,部署到生产环境之后,外界手机APP应用调用,发现其响应速度在0.5秒到6秒之间波动,客户已经为此纠结了2星期了。昨天我应邀帮他们搞定这问题,在许多同事的共同帮助下,终于把这个问题圆满解决。这里分享下全过程。
方法论:
模拟整体过程,分段解析,精确定位故障点。 此方法论适用于一切troubleshooting过程(就像在地板上找针,需要把地板划分为一个一个小格子,找过的格子就标记下,这样更容易找到针)
首先,需要对我们的请求过程做充分的了解,以登录接口为例,我们就有了以下的一个抽象的网络拓扑图:
然后我们就开始分段排错,因为整个过程是同步调用并且是对称的,所以只考虑(1)->(11),而不考虑(12)->(20)。
具体实践:
步骤1 ,确定客户端到应用服务器的网络通信质量。
从Python客户端测试机器去ping 应用服务器的外网地址,测试了1000次后,发现其pin还是挺稳定的,基本都在20毫秒之内,如下图:
所以一下子就排除了拓扑图中的 (1),(2),(3),(4),(5)这么多段。
步骤2:确定其原因不是由我们程序员代码的内部业务逻辑所导致。
为此,我们让开发人员在登录接口中屏蔽了一切和外部通信的部分,也就是不调用技术部接口(注释掉这段代码),只在Spring框架进入Service方法和服务完分别打印下服务器的当前时间戳,然后相减获得实际内部代码业务逻辑(比如请求分流,字符串拼接,数据库操作等),这时候再绘制耗时的曲线图,如下:
从这里看出,我们内部逻辑的总用时平均才77毫秒,虽然最多有420毫秒,但是对于300的样本容量来说,这只能算极个别的特例的噪音数据,所以我们代码业务逻辑耗时正常,这就排除了(6)和(9)
然后我们隔离掉自身业务逻辑,又重新做了一个接口,让其只调用技术部的web service,这次发现其图很有规律(规律我后面会说),此图如下:
发现它最多还是会用时5秒,而且几乎类似脉冲。
步骤3:确定需要深入剖析的可疑点。
这样看来,可疑点有三段:
-
(7)和(8)。也就是应用服务器(Tomcat)通过Http(https) Connector转发请求到Spring容器,然后Spring容器通过Spring框架的DispatcherServlet转发请求到相应的bean的业务方法。
-
(10)这段。也就是从Spring中的bean方法发送请求mapi.XXX.com这个web service调用中间的网络。
-
(11)这段。也就是技术部接口本身调用服务的耗时。
当然,大家brainstorming之后还有一些假设。
-
JAVA平台本身的性能问题。
-
代码中Web Service连接使用后未关闭导致连接过多响应变慢。
-
内存泄露导致服务器性能急剧下降。
-
Full GC导致特定时间内服务器性能奇差无比。
当然了,D这个可以忽略,因为JAVA作为一种平台语言,其高效的性能已经被无数例子证明了,要有严重性能问题早被发现了,不会到现在刚好被我们运气好才发现。
步骤4:排除技术部接口本身的问题(11这段)。
这方面感谢技术部专家的协助,他们送来了技术部接口本身内部调用的时间开销原始数据,样本容量在1400个左右,我们用代码分析并画图,可以看到以下曲线图:
从曲线分布可以看到,虽然有极个别的要13秒的(可以认为超时了),其他时间基本都控制在1-2秒左右。 因为他们最终接口也要调用新浪IP地址库这些外部接口,所以个别的噪音数据也是能容忍的。所以这张图说明技术部接口工作正常。
步骤5:排除Web Service连接未关闭的问题:
我特地去看了下代码,发现WebService连接并发送GET请求后使用完被优雅的关闭了,如下:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
|
public
static
HttpClientResponsegetMethod(String url) {
HttpClient client = newHttpClient();
StringBuilder resContentBuf = newStringBuilder();
GetMethod method = newGetMethod(url);
// Provide custom retry handler is necessary
method.getParams().setParameter(HttpMethodParams.RETRY_HANDLER, newDefaultHttpMethodRetryHandler(
3
,
false
));
intstatusCode =
0
;
try
{
statusCode = client.executeMethod(method);
if
(statusCode == HttpStatus.SC_OK || statusCode ==
400
) {
resContentBuf.append(method.getResponseBodyAsString());
}
}
catch
(Exception e) {
e.printStackTrace();
}
finally
{
method.releaseConnection();
}
logger.info(
"HttpClientUtil.getMethod,the json data:"
+resContentBuf.toString());
return
assembleResponse(resContentBuf.toString(),statusCode);
}
|
而且如果是连接未关闭的话,应该是开始快,随着测试次数变多越来越慢,而不是像步骤2的第二张图那样,第一次耗时那么长(5秒)
步骤6:排除内存泄露导致的性能下降问题。
为此,我让同事再次运行单独调用技术部接口的web service 300次,在此期间通过5个时间点分别截取heapdump来分析内存泄露。
Step 1: ps –ef | grep java 获取登录接口的进程ID
Step2: cd $JAVA_HOME\bin
jmap -dump:format=b,file=/tmp/heapdump.hprof <pid> 把运行的进程ID传入,然后用jmap工具来获得堆dump信息。
然后利用Eclipse的MAT(Memory Analyze Tool)插件来分析可能的leak point ,此插件下载地址在http://download.eclipse.org/mat/1.3/update-site/,在截取了5个巨大的heapdump文件之后,我对比了这5个点(开始,中间1,中间2,中间3,结束)的内存状况和可能的leak点,(主要关注对象的 retained Size, 它表示释放该对象会额外释放多少内存空间)
开始:
中间1:(2,3略了,几乎相同)
结束:
而且几个SuspensionPoint,经过对象引用树的逐层深入排查,也和我们的代码无关,所以可以排除内存泄露的情况。
步骤7:排除GC导致的可能导致的延时。
为此,我在Tomcat启动时候,加了如下的JAVA_OPTION: -XX:+PrintGCApplicationStoppedTime,这个选项的作用是打印垃圾回收期间程序暂停的时间。
正如我所料,执行一次Full GC大概需要41秒,这比才5秒的波峰延迟要高出太多。显然不可能。
我把性能参数做了一些优化:
首先,因为Tomcat7 支持NIO,它性能比IO要高很多,所以我在Connector上配置了NIO
1
2
3
4
5
6
7
8
9
10
|
<
Connector
port
=
"xxx"
protocol
=
"org.apache.coyote.http11.Http11NioProtocol"
connectionTimeout
=
"20000"
URIEncoding
=
"UTF-8"
useBodyEncodingForURI
=
"true"
maxThreads
=
"768"
minSpareThreads
=
"64"
enableLookups
=
"false"
redirectPort
=
"8443"
/>
|
请求延迟依然没本质改变,还是5秒左右波峰,不增也不减。
步骤8:排除应用服务器(Tomcat)通过Http(https) Connector转发请求到Spring容器,然后Spring容器通过Spring框架的DispatcherServlet转发请求到相应的bean的业务方法(7和8这段)。
虽然打印出一个请求从应用服务器中间件到Spring再到bean业务方法的时间请求很困难,但是可以做其他实验。我们拿步骤3中实现的只包含这个内部处理逻辑的bean方法为例子。让手机客户端或者客户端测试代码去请求这个bean 方法,获得的时间曲线大概如下:
其平均用时在591毫秒,而且最长也不到2秒,减去步骤2 图1的平均用时77毫秒,可以判断,应用服务器中间件和框架层面的处理平均用时在500毫秒左右。这显然也排除了应用服务器和框架层面。
步骤9:查看应用服务器和技术部接口的通信。
因为其他部分都证明没问题了,所以用反证法得知这段肯定有问题。为了证明,前天我让同事写了2个新的webservice方法,一个是直接通过域名调用技术部接口的,一个是通过外网IP技术部接口的。
方法1:publicstaticLoginUserInfoVo getUserInfoFromBLN(String loginName, String loginPassword)
方法2:publicstaticLoginUserInfoVo getUserInfoFromBLNByIP(String loginName, String loginPassword){
非常可惜,第二个方法(通过IP的方法)无法调用成功,原因也很容易理解,肯定技术部接口也是有地址映射的,所以某个请求URL肯定是IP和端口组合然后映射到的地址,所以单纯靠IP替换无法发送成功。
昨天深入分析的时候,我又从步骤2的第二张图看出了一些规律:不仅此接口,几乎所有其他连接技术部的接口都是第一次调用很慢,大概5秒多,接下来的调用速度会很快。精确的过36秒后,出现第二次波峰,依次类推。因为每次都是36秒间隔,这个更像是在哪里配置的。但这个可以确定就是应用服务器到技术部接口的通信通道上。
最后我们找到了原因,原来在应用服务器上配置的DNS是114.114.114.114,这是个公共DNS服务。它导致我们首次请求技术部接口时候要往外网绕一圈才回来。这就解释了为什么所有图的第一次请求都要超过5秒。随后,这个DNS解析结果缓存在应用服务器上,并且缓存时间间隔在36秒左右。这就解释为什么接下来的36秒内每次请求速度都极快(在500毫秒以内),然后直到精确的36秒才出现第二个大于5秒的波峰。
步骤10:重做实验验证结论。
我们重更新了/etc/hosts文件,因为其解析优先级高于DNS解析,所以请求不再通过114.114.114.114从外网兜圈再回技术部接口。我们又把其他调用技术部接口的场景都做了测试。果然经过改动后,图形再也不是一开始的脉冲了,而且很稳定,最长也就1.5秒,平均下来也就600毫秒的样子,完全满足我们要求,说明我们这个问题完美解决了。