分享一次分析解决支付应用性能问题的全过程，细节和采用的工具和方法

分享一次分析/解决支付应用性能问题的全过程，细节和采用的工具和方法

引入：

当我们做的某支付系统，以一组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：确定需要深入剖析的可疑点。

这样看来，可疑点有三段：

1. (7)和(8)。也就是应用服务器(Tomcat)通过Http(https) Connector转发请求到Spring容器，然后Spring容器通过Spring框架的DispatcherServlet转发请求到相应的bean的业务方法。

2. (10)这段。也就是从Spring中的bean方法发送请求mapi.XXX.com这个web service调用中间的网络。

3. (11)这段。也就是技术部接口本身调用服务的耗时。

 

当然，大家brainstorming之后还有一些假设。

1. JAVA平台本身的性能问题。

2. 代码中Web Service连接使用后未关闭导致连接过多响应变慢。

3. 内存泄露导致服务器性能急剧下降。

4. Full GC导致特定时间内服务器性能奇差无比。

 

当然了，D这个可以忽略，因为JAVA作为一种平台语言，其高效的性能已经被无数例子证明了，要有严重性能问题早被发现了，不会到现在刚好被我们运气好才发现。

 

 

步骤4：排除技术部接口本身的问题（11这段）。

这方面感谢技术部专家的协助，他们送来了技术部接口本身内部调用的时间开销原始数据，样本容量在1400个左右，我们用代码分析并画图，可以看到以下曲线图：

从曲线分布可以看到，虽然有极个别的要13秒的（可以认为超时了），其他时间基本都控制在1-2秒左右。 因为他们最终接口也要调用新浪IP地址库这些外部接口，所以个别的噪音数据也是能容忍的。所以这张图说明技术部接口工作正常。

 

 

步骤5：排除Web Service连接未关闭的问题：

我特地去看了下代码，发现WebService连接并发送GET请求后使用完被优雅的关闭了，如下：

 

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

 
 <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毫秒的样子，完全满足我们要求，说明我们这个问题完美解决了。