引入：
当我们做的某支付系统，以一组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毫秒的样子，完全满足我们要求，说明我们这个问题完美解决了。
