服务端性能问题排查及优化 - 响应时间长问题分析

二叶草 2020年2月1日13:21:03优化评论阅读模式

服务端性能问题排查及优化 - 响应时间长问题分析

响应时间长有很多叫法,比如高延迟、服务器反应慢、业务超时等,最根本的表现就是客户端发送请求到服务端后,服务器很长时间才给应答或者根本就没给应答。

造成响应时间长的原因有很多,比如:

1.服务端应用压力太大,确实处理不过来了

2.使用了不恰当的同步锁(代码级别或者其他资源锁)

3.第三方资源的不给力

4.线程池配置的不合理,线程数配置的太少导致的请求积压

5.网络原因,丢包、带宽限制、重传等

6.sleep

7.调用端代码有问题导致服务器应答到达客户端后,客户端处理不及时,可能也会误认为响

应时间长

 分析方法

用到的工具

  • jvisualvm
    用于实时的监控每个方法的执行时间,统计比较精但不适合线上长时间使用。
  • jstack
    抓取应用当前的线程堆栈信息,分析每个线程正在执行的操作。

通过jvisualvm分析

通过jvisualvm分析能够更直观的看到每个方法的执行时间,在测试环境或者开发阶段调优非常有帮助。
首先,打开jvisualvm,jvisualvm位于jdk的bin目录下,一般配置了jdk的环境变量可以直接通过命令行输入jvisualvm打开。另外也可以通过https://visualvm.github.io/去下载直接使用。
打开后界面如下:

服务端性能问题排查及优化 - 响应时间长问题分析

如果是本地应用,可以直接点击需要监控的进程,直接挂载上去。
如果是远程应用,需要在远程应用启动的时候,添加允许远程调试的参数。

-Dcom.sun.management.jmxremote.port=8999 
-Dcom.sun.management.jmxremote.ssl=false 
-Dcom.sun.management.jmxremote.authenticate=false 
-Djava.rmi.server.hostname=远程机器IP

挂载成功后点击抽样器标签,抽样选择CPU,点击完后就开始监控了。

服务端性能问题排查及优化 - 响应时间长问题分析

监控一段时间后,一般几十秒后就可以了,点击快照抓取监控的快照,为了保险可以在运行几十秒后再抓取一次快照,为了对比确定问题。然后就可以停止监控了。
快照抓取成功后会在最右侧的标签中展示,如下图:

服务端性能问题排查及优化 - 响应时间长问题分析

打开第一次的快照,选择热点标签,按总时间排序,排序后左侧的方法区就是执行时间比较长的方法。如下图所示。但是这其实不是我们想要的,你应该能看到执行时间长的都是些select、wait、sleep等,这些类似一些基本操作的方法,执行的次数比较多,还有就是设计的就是要等待的操作,所以执行的时间比较长。

服务端性能问题排查及优化 - 响应时间长问题分析

比较靠谱的做法是,我们先大概过一下,如果没有明显的有问题的方法的话,而且方法也很多的话,可以根据包名过滤一下,只关注我们自己的东西,看看我们开发的方法中那些方法执行时间比较长。比如如下所示,我过滤下com.jd包的方法。

服务端性能问题排查及优化 - 响应时间长问题分析

还是没发现明显问题,方法也比较多,接着缩小范围,过来com.jd.jr命名空间

服务端性能问题排查及优化 - 响应时间长问题分析

此时可以发现一些执行时间比较长的方法,发现以后可以通过右键在调用树中查找,确定该方法执行时间长具体是因为哪一步导致的。如下图:

服务端性能问题排查及优化 - 响应时间长问题分析

服务端性能问题排查及优化 - 响应时间长问题分析

现在可以发现,执行时间戳是因为本地的test调用远端的test方法导致的,可以查看远程的test代码优化了。
远程的test方法其实就是一个sleep来模拟处理时间。

public class TaskServiceImplMock implements TaskService {
    private static final Logger LOGGER = LoggerFactory.getLogger(TaskServiceImplMock.class);
    @Override
    public String test(String str) {
        LOGGER.info("test ok.");
        try {
            Thread.sleep(2000);
        } catch (InterruptedException e) {
        }
        return "Test " + str + "OK";
    }

通过线程堆栈分析

生产环境中,大多数情况下没有条件通过jvisualvm的方式分析,因此只能通过执行堆栈来分析。
通过堆栈分析的话,最好是在应用出问题提交明显的情况下分析。
线程分析的根本为同一时间点同时执行某项任务的几率比较低,每次都被抓到的概率更低,如果每次都有相同的执行堆栈被抓取到,那肯定是有原因的,要么是长态任务,要么是有问题。

抓取线程堆栈

首先通过jstack命令抓取线程的执行堆栈,连续抓取3次对比用,每次间隔几秒。 jstack 进程ID > /tmp/文件名.jstack

分析

分析抓取的线程堆栈,这个比较麻烦,需要你对该应用有一定的了解,能够看到堆栈大概知道所对应的功能。
大概堆栈文件后,先大概的过一遍堆栈的信息,线程数比较多的话,可能要通过以下统计的方法过一下,要知道这么多线程中每个种类线程执行的操作的一个分布,比如多少io线程,每个线程池多少线程,多少wait线程等。
一般情况下响应时间长,在线程堆栈上的表现为有大量的线程在执行同一个操作,或者有大量线程在等同一个资源,在检查堆栈的时候我们可以重点去观察一下。

上面的实例的堆栈中有很多如下的线程堆栈,通过此堆栈也能看到是在执行sleep方法,且能很明了的看到整个线程的堆栈。
真实的场景中问题问题可能不会这么明显,需要通过对业务的了解去排除其他正常的执行堆栈。

"JSF-BZ-22000-9-T-180" #257 daemon prio=5 os_prio=31 tid=0x00007fa1a59d5000 nid=0x12d07 waiting on condition [0x00007000102e9000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at com.jd.jr.app.jsf.impl.TaskServiceImplMock.test(TaskServiceImplMock.java:17)
        at sun.reflect.GeneratedMethodAccessor9.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.jd.jsf.gd.filter.ProviderInvokeFilter.reflectInvoke(ProviderInvokeFilter.java:140)
        at com.jd.jsf.gd.filter.ProviderInvokeFilter.invoke(ProviderInvokeFilter.java:100)
        at com.jd.jsf.gd.filter.ProviderConcurrentsFilter.invoke(ProviderConcurrentsFilter.java:62)
        at com.jd.jsf.gd.filter.ProviderTimeoutFilter.invoke(ProviderTimeoutFilter.java:39)
        at com.jd.jsf.gd.filter.ProviderMethodCheckFilter.invoke(ProviderMethodCheckFilter.java:78)
        at com.jd.jsf.gd.filter.ProviderInvokeLimitFilter.invoke(ProviderInvokeLimitFilter.java:54)
        at com.jd.jsf.gd.filter.ProviderHttpGWFilter.invoke(ProviderHttpGWFilter.java:47)
        at com.jd.jsf.gd.filter.ProviderGenericFilter.invoke(ProviderGenericFilter.java:118)
        at com.jd.jsf.gd.filter.ProviderContextFilter.invoke(ProviderContextFilter.java:73)
        at com.jd.jsf.gd.filter.ExceptionFilter.invoke(ExceptionFilter.java:49)
        at com.jd.jsf.gd.filter.FilterChain.invoke(FilterChain.java:275)
        at com.jd.jsf.gd.server.ProviderProxyInvoker.invoke(ProviderProxyInvoker.java:67)
        at com.jd.jsf.gd.server.JSFTask.doRun(JSFTask.java:118)
        at com.jd.jsf.gd.server.BaseTask.run(BaseTask.java:27)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

示例 - 锁等待导致的响应时间长

在遇到堆栈中有大量的BLOCKED线程的情况下,需要确定是不是用了某些不合适的同步锁。
以下是一个锁等待导致的响应时间长的堆栈信息的摘取,可以看到大量的堆栈都在waiting一个lock。
另外,线程池中没有任务,或者大量的Queue的等待的话,线程池中的线程也会是blocked或者wait的状态,但是这个是正常的,因为他就是没事可做,在等待任务。

"Thread-96" #116 prio=5 os_prio=0 tid=0x00007f4efc677800 nid=0x2ba9 waiting for monitor entry [0x00007f4e69ddc000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at main.java.demo.delay.Client.testDelay(Client.java:47)
    - waiting to lock <0x0000000785cd4748> (a java.lang.Class for main.java.demo.delay.Client)
    at main.java.demo.delay.Client$1.run(Client.java:31)
    at java.lang.Thread.run(Thread.java:745)
"Thread-95" #115 prio=5 os_prio=0 tid=0x00007f4efc675800 nid=0x2ba8 waiting for monitor entry [0x00007f4e69edd000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at main.java.demo.delay.Client.testDelay(Client.java:47)
    - waiting to lock <0x0000000785cd4748> (a java.lang.Class for main.java.demo.delay.Client)
    at main.java.demo.delay.Client$1.run(Client.java:31)
    at java.lang.Thread.run(Thread.java:745)
"Thread-94" #114 prio=5 os_prio=0 tid=0x00007f4efc673800 nid=0x2ba7 waiting for monitor entry [0x00007f4e69fde000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at main.java.demo.delay.Client.testDelay(Client.java:47)
    - waiting to lock <0x0000000785cd4748> (a java.lang.Class for main.java.demo.delay.Client)
    at main.java.demo.delay.Client$1.run(Client.java:31)
    at java.lang.Thread.run(Thread.java:745)
"Thread-93" #113 prio=5 os_prio=0 tid=0x00007f4efc671800 nid=0x2ba6 waiting for monitor entry [0x00007f4e6a0df000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at main.java.demo.delay.Client.testDelay(Client.java:47)
    - waiting to lock <0x0000000785cd4748> (a java.lang.Class for main.java.demo.delay.Client)
    at main.java.demo.delay.Client$1.run(Client.java:31)
    at java.lang.Thread.run(Thread.java:745)
"Thread-92" #112 prio=5 os_prio=0 tid=0x00007f4efc66f800 nid=0x2ba5 waiting for monitor entry [0x00007f4e6a1e0000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at main.java.demo.delay.Client.testDelay(Client.java:47)
    - waiting to lock <0x0000000785cd4748> (a java.lang.Class for main.java.demo.delay.Client)
    at main.java.demo.delay.Client$1.run(Client.java:31)
    at java.lang.Thread.run(Thread.java:745)

示例 - 第三方资源响应时间长

第三方的资源有问题导致调用方响应时间长的话,和锁等待的堆栈有点类似。

  • 如果请求第三方为单线程则比较简单,直接查看该线程的堆栈,如果每次抓堆栈信息都能看到在请求第三方资源的话,那说明就是有问题了,因为在响应时间很短的情况下,你不大可能每次都能抓到请求中的堆栈。
  • 如果是多线程访问的话,查看线程堆栈中是不是同时有很多线程同时在执行这些操作,如果有,则需要考虑是不是第三方资源有问题了,同第一次条原因,在响应时间很短的情况下,能抓到很多线程都在执行某一个操作,不太容易。

本文来源于:[前端工坊]服务端性能问题排查及优化 - 响应时间长问题分析-变化吧门户
特别声明:以上文章内容仅代表作者本人观点,不代表变化吧门户观点或立场。如有关于作品内容、版权或其它问题请于作品发表后的30日内与变化吧联系。

  • 赞助本站
  • 微信扫一扫
  • weinxin
  • 加入Q群
  • QQ扫一扫
  • weinxin
二叶草
nginx解析漏洞 优化

nginx解析漏洞

phpstudy(小皮模板存在nginx解析漏洞) 影响版本 phptsuy8.1.07的Nginx1.5.11版本影响版本 phptsuy8.1.07的Nginx1.5.11版本 phpstudy介...
网站SEO优化基础流程(新手必看) 优化

网站SEO优化基础流程(新手必看)

宝塔面板搭建一个获取网站的Favicon图标的APIgetFavicon是一个可以获取网站的Favicon图标并显示在你的网页上的项目。安装方法很简单,属于开箱即食。这篇文章还是基于宝塔面板来搭建。 ...

发表评论