现象描述

不管是性能测试中，还是生产环境中，经常会遇到响应时间过长的问题。

响应时间是性能评估的一个重要指标，会对最终用户产生直接影响，一个产品是快是慢，响应时间是最直观的感受。

因此面对响应时间长的问题，一定想尽办法消灭它。

以下定位方法是针对比较典型的nginx+tomcat应用架构。

排查思路及方法说明

常见有两种表现：偶现极少量的请求出现响应时间偏长，或者会有大量、批量的请求响应时间长。

对偶然出现的少量响应时间长的问题，可能是外部影响、网络异常等造成。

偶然出现少量响应时间过长时，可以排查以下几个方面来定位问题，

查看当时服务器日志是否有错误；

检查服务器资源使用情况是否正常，load average、CPU使用率(尤其是单核CPU)是否有飙高现象；

检查是否出现磁盘短暂负载较高，比如iostat util%飙高等；

确认当时网络情况是否正常，是否有网络丢包等现象。

以上排查建议在有全面监控的基础上进行，偶现问题比较难定位，有全面的监控数据进行排查就方便多了。

案例1：单核CPU使用率高导致偶现响应时间长

某产品线上出现少量的响应时间长的问题，定位结果发现是两个CPU密集型服务部署在同一台机器上，

其中一个服务会使得单个CPU使用率100%，导致另一个服务出现少量请求响应慢。解决办法是服务隔离。

如果出现比较多的响应时间过长，首先要排查所有服务器是否存在资源使用瓶颈，

如CPU使用率高、单核CPU使用率高、内存使用是否正常、是否有频繁FullGC、磁盘IO压力情况、网路时延情况等。

如果不能通过以上检查发现问题所在，那就要逐步分析是系统架构中哪个环节导致的问题。

nginx排查

首先排查nginx access.log日志，分析响应时间可能慢在哪里。

log_format中定义了$request_time字段，它指的是从接受用户请求数据到发送完回复数据的时间。

那究竟是慢在了nginx还是上游服务器？

log_format同时提供了$upstream_response_time字段，它是指从nginx向后端建立连接开始到接受完数据然后关闭连接为止的时间。

那就是说：

如果两者相差很大，也即是$upstream_response_time数值比较小，则需要查看nginx模块配置或nginx与客户端的网络是否有性能瓶颈了。

如果r e q u e s t t i m e 与 request_time与requestt​ime与upstream_response_time相差不大，则可能是nginx连接上游服务器比较慢，或者上游服务比较慢，需要进入下一步应用层排查。

案例2：nginx日志排查出网络问题

一线上产品出现某个操作响应时间30%以上都大于2s，通过分析access.log发现r e q u e s t t i m e 与 request_time与requestt​ime与upstream_response_time相差不大，

进一步检查nginx的配置，以及nginx服务器所在的交换机流量发现，nginx所在交换机流量基本快跑满了，导致nginx返回数据较慢。

nginx层排查除了以上日志排查外，还需要关注nginx本身的配置，比如nginx worker_connections设置过小会导致响应时间长，tps上不去，具体可参考上一期《tps上不去》。

应用层排查

排除Nginx层的问题，那要着重定位应用层自身代码、或者第三方调用、或者数据库等其它依赖服务是否存在响应慢的情况。

首先确认是否存在以下问题：

确认应用服务是否有某些线程CPU使用率高，通过top -H可以方便实时查看

确认线程是否存在异常状态，如频繁blocked、死锁等，推荐使用visualVM、Jconsole、jstack查看线程状态，进行线程dump

连接数检查，应用层连接数设置过小，会导致响应时间长，tps上不去，可以参考上一期《tps上不去》问题

如果有产品内部监控，如典型业务调用的处理时间、慢操作日志监控，那就比较方便了

如果很不幸，监控数据很少，且现有数据难以分析，那推荐两个百试不爽的分析工具，Nprofile和Btrace。

Btrace在线调试神器

BTrace 是一款利用hotSpot虚拟机可以动态替换class的特点而完成的，可以对online的程序动态的改变类的行为, 进而进行线上调试的一个工具。

也就是说可以不需要重启服务可以直接在线调试分析。关于Btrace的教程随意搜索就能找到很多。

案例3：Btrace在线分析

生产环境出现某种请求有30%的比例响应时间比较长，需要定位具体是哪个接口或调用响应时间长。

1、首先要了解应用层的调用关系，我们对com.netease.XXX.usercenter.web.dwr.YYYBean进行跟踪，完成Btrace脚本：

@BTrace

public class LessonLearnRecordServiceImpl {

@TLS

static long beginTime;

@OnMethod(clazz = "/com.netease.XXX.usercenter.web.dwr.YYYBean/", method = "/.+/")

public static void traceExecuteBegin() {// 在方法btrace.test.MyBtraceTest.execute()执行之前进行监控。

beginTime = timeMillis();

// 监控行为是记录一个开始时间。

}

// OnMethod代表运行一个方法的时候进行监控，location @Location(Kind.RETURN)代表在方法返回的时候触发监控行为。

@SuppressWarnings("deprecation")

@OnMethod(

clazz = "/com.netease.XXX.usercenter.web.dwr.YYYBean/",

method = "/.+/",

location = @Location(Kind.RETURN)

)

public static void traceExcute() {

// 监控行为是根据开始时间计算出方法运行时间。

print(strcat("entered ", name(probeClass())));

print(strcat(".", probeMethod()));

println(strcat(" taken : ",strcat(str(timeMillis() - beginTime), "ms")));

}

}

2、获取服务的进程PID，启动Btrace agent：btrace

查看生成的日志如下：

entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 818ms

entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 619ms

entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 930ms

entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 613ms

entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 515ms

entered com.netease.XXX.usercenter.web.dwr.YYYBean.updateVideoTime taken : 716ms

观察日志发现updateVideoTime方法大部分调用时间大于500ms，基本能判断是该方法需要进行性能优化。

Nprofile分析调用热点

Nprofile也即是AJprofile，是由何卓斌开发的一个自身开销比较小，可以profile调用时间和调用热点的小工具。

原理是在需要跟踪的函数调用前后通过AOP调用一些计时的代码，并进行一些简单的统计处理。

使用说明参考:http://doc.hz.netease.com/pages/viewpage.action?pageId=25690763(内部资料)

案例4: 循环调用导致响应时间长

某web应用，一个Http get请求，性能测试最高tps240，平均响应时间接近1s，CPU使用偏高。不满足性能测试通过条件。

对该接口进行profile：

可以发现一次getMyCourse，会有十几次的getFirstLesson和getLastestLearnedLesson调用。

经过确认，确实存在无用的循环调用问题。解决后性能有30%以上的提升。

Nprofile堪称利器，在性能问题分析和定位中非常有效，且比Jprofiler轻便，开销小，对性能测试结果影响小。

数据库层排查

通常web应用会有大量的数据库操作，数据库性能对web应用的性能表现至关重要。如果应用层的分析发现大量线程

等待数据库的响应，就需要对数据库层进行排查。最常见的数据库性能问题有：

索引缺失或者索引建的不合理，sql语句不合理导致没有走索引，进而导致SQL的执行时间长

SQL语句自身写的有问题，导致执行时间比较长

锁等待和锁超时导致事务回滚以致于响应时间很长

数据库的配置不合理，例如最大并发连接过小，bufferpool的设置过小等引起的性能问题

案例5：未创建索引导致响应时间长，CPU飙高

某接口tps只有150时，cpu使用率飚满，且响应时间大于1s。通过Nprofile分析，

发现其中一个方法调用消耗了99%的CPU调用，该方法主要是进行数据库读操作，检查数据库发现未创建索引。

解决后tps上升一倍，响应时间下降到250ms左右。

数据层性能问题可以通过Mysql监控、或mysql-slow.log进一步详细分析。