问题发现

事情是这样的，最近小码仔负责的项目预定今天凌晨2点上进行版本更新。前几天测试小姐姐对网站进行压力测试，观察服务的CPU、内存、load、RT、QPS等各种指标。

在压测的过程中，测试小姐姐发现我们其中一个接口，在QPS上升到400以后，CPU利用率急剧升高。

在这里我不再对CPU、内存、load、RT、QPS等做过多赘述，毕竟这几个点中的任何一个拿出来探讨，一篇文章都不一定写的完。有兴趣深究的小可爱就自己动手查一下吧。

这里我仅对QPS及CPU利用率做简单的概述。

❝

QPS每秒查询率，QPS是对一个特定的查询服务器在规定时间内所处理流量多少的衡量标准。QPS越高说明，在特定时间内服务器所处理的流量越大。

❞

❝

CPU利用率是来描述CPU的使用情况，它表明了一段时间内CPU被占用的情况。使用率越高，说明机器在这个时间上运行了很多程序，反之较少。

❞

了解了这两个基本的点，接下来就来一起看看我具体是怎么定位的吧。

问题定位

测试小姐姐反馈这个问题后，我登录到服务器，做了以下操作：

1.定位进程

登录服务器，执行top命令，查看CPU占用情况：

$top   PID  USER      PR   NI  VIRT   RES    SHR   S  %CPU   %MEM   TIME+  COMMAND  44529 root     20   0  4289m   874m  13312  S  123.0   10.9   10:39.73  java

top命令查看所有进程占系统CPU的排序，它是Linux下常用的性能分析工具，能够实时显示系统中各个进程的资源占用状况，类似于Windows的任务管理器。

我们来看一下这些指示符代表什么：

PID — 进程idUSER — 进程所有者PR — 进程优先级NI — nice值。负值表示高优先级，正值表示低优先级VIRT — 进程使用的虚拟内存总量，单位kb。VIRT=SWAP+RESRES — 进程使用的、未被换出的物理内存大小，单位kb。RES=CODE+DATASHR — 共享内存大小，单位kbS — 进程状态。D=不可中断的睡眠状态 R=运行 S=睡眠 T=跟踪/停止 Z=僵尸进程%CPU — 上次更新到现在的CPU时间占用百分比  %MEM — 进程使用的物理内存百分比  TIME+ — 进程使用的CPU时间总计，单位1/100秒  COMMAND — 进程名称(命令名/命令行)

通过执行top命令，我看到，进程ID为44529的Java进程的CPU占用率达到了123%，基本可以定位到是我们的Java应用导致整个服务器的CPU占用率飙升。

2.定位线程

当然，Java是单进程多线程的，那么，接下来我就看了这个PID=44529的这个Java进程中的各个线程的CPU使用情况，同样是用top命令：

$top -Hp 44529   PID  USER     PR   NI  VIRT  RES     SHR   S  %CPU   %MEM    TIME+  COMMAND  44580 root     20   0   4289m 874m   13312  S  16.2   10.9    3:02.96   java

通过执行top -Hp 44529命令，我发现，在44529这个进程中，ID为44580的线程占用CPU最高。

3.定位代码

通过top命令，我定位到了导致CPU使用率较高的具体线程， 接下来就要看一下具体是哪一行代码存在问题。

首先，我把44580这个线程转成16进制：

$printf %x 44580ae24

接下来，根据该16进制值去打印的堆栈日志内查询，查看该线程所驻留的方法位置。并通过jstack命令，查看栈信息：

$jstack 44529 |grep -A 200 ae24"System Clock" #28 daemon prio=5 os_prio=0 tid=0x00007efc19e8e800 nid=0xae24 waiting on condition [0x00007efbe0d91000]   java.lang.Thread.State: TIMED_WAITING (sleeping)    at java.lang.Thread.sleep(Native Method)    at java.lang.Thread.sleep(Thread.java:340)    at java.util.concurrentC.TimeUnit.sleep(TimeUnit.java:386)    at com.*.order.Controller.OrderController.detail(OrderController.java:37)  //业务代码阻塞点

通过以上代码，我们可以清楚的看到，OrderController.java的第37行是有可能存在问题的。

然后我找到项目中OrderController.java的第37行，仔细分析发现由于自己的粗心，代码存在逻辑上的漏洞。修改重构之后，问题解决。

总结

以上就是本次问题排查的整个过程。主要用到的有:top，printf，jstack等指令。

  1. 使用top指令查看当前占用CPU较高的进程PID；
  2. 查看当前进程消耗资源的线程PID： top -Hp PID
  3. 将线程PID转为16进制，根据该16进制值去打印的堆栈日志内查询，查看该线程所驻留的方法位置。
  4. 通过jstack命令，查看栈信息，这步基本上已经能够定位大多数问题了。


作者：马尾