编辑推荐

网易数帆开源API网关与容器云项目，让云原生生产落地“多快好

网易汪源：统一负载与多云环境的“开放姿态”，才是云原生

网易数帆如何用 Kubernetes“原语”搞定云原生中间件

快手打新挤爆券商系统，网易数帆推出券商稳定性保障方案

探索智慧校园新模式，网易有数在教育行业的实践分享

金融行业大数据治理之路——数据模型篇

响应时间过长问题分析

未来已来2018-09-06 12:23

作者：刘林霞

现象描述

不管是性能测试中，还是生产环境中，经常会遇到响应时间过长的问题。
响应时间是性能评估的一个重要指标，会对最终用户产生直接影响，一个产品是快是慢，响应时间是最直观的感受。
因此面对响应时间长的问题，一定想尽办法消灭它。
以下定位方法是针对比较典型的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向后端建立连接开始到接受完数据然后关闭连接为止的时间。
那就是说：
1. 如果两者相差很大，也即是$upstream_response_time数值比较小，则需要查看nginx模块配置或nginx与客户端的网络是否有性能瓶颈了。
2. 如果$request_time与$upstream_response_time相差不大，则可能是nginx连接上游服务器比较慢，或者上游服务比较慢，需要进入下一步应用层排查。

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

一线上产品出现某个操作响应时间30%以上都大于2s，通过分析access.log发现$request_time与$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%以上的提升。