线上性能问题初步排查方法

标签： linux | 发表时间：2014-10-15 23:00 | 作者：方 腾飞
出处：http://ifeve.com


引言

有时候有很多问题只有在线上或者预发环境才能发现，而线上又不能Debug，所以线上问题定位就只能看日志，系统状态和Dump线程，本文只是简单的介绍一些常用的工具，帮助定位线上问题。

问题定位

1: 首先使用TOP命令查看每个进程的情况，显示如下：

top - 22:27:25 up 463 days, 12:46, 1 user, load average: 11.80, 12.19, 11.79
 Tasks: 113 total, 5 running, 108 sleeping, 0 stopped, 0 zombie
 Cpu(s): 62.0%us, 2.8%sy, 0.0%ni, 34.3%id, 0.0%wa, 0.0%hi, 0.7%si, 0.2%st
 Mem: 7680000k total, 7665504k used, 14496k free, 97268k buffers
 Swap: 2096472k total, 14904k used, 2081568k free, 3033060k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 31177 admin 18 0 5351m 4.0g 49m S 301.4 54.0 935:02.08 java
 31738 admin 15 0 36432 12m 1052 S 8.7 0.2 11:21.05 nginx-proxy

我们的程序是Java应用，所以只需要关注COMMAND是Java的性能数据，COMMAND表示启动当前进程的命令，在Java进程这一行里可以看到CPU利用率是300％，不用担心，这个是当前机器所有核加在一起的CPU利用率。

2: 再使用Top的交互命令数字1查看每个CPU的性能数据。

top - 22:24:50 up 463 days, 12:43, 1 user, load average: 12.55, 12.27, 11.73
 Tasks: 110 total, 3 running, 107 sleeping, 0 stopped, 0 zombie
 Cpu0 : 72.4%us, 3.6%sy, 0.0%ni, 22.7%id, 0.0%wa, 0.0%hi, 0.7%si, 0.7%st
 Cpu1 : 58.7%us, 4.3%sy, 0.0%ni, 34.3%id, 0.0%wa, 0.0%hi, 2.3%si, 0.3%st
 Cpu2 : 53.3%us, 2.6%sy, 0.0%ni, 34.1%id, 0.0%wa, 0.0%hi, 9.6%si, 0.3%st
 Cpu3 : 52.7%us, 2.7%sy, 0.0%ni, 25.2%id, 0.0%wa, 0.0%hi, 19.5%si, 0.0%st
 Cpu4 : 59.5%us, 2.7%sy, 0.0%ni, 31.2%id, 0.0%wa, 0.0%hi, 6.6%si, 0.0%st
 Mem: 7680000k total, 7663152k used, 16848k free, 98068k buffers
 Swap: 2096472k total, 14904k used, 2081568k free, 3032636k cached

命令行显示了CPU4，说明这是一个5核的虚拟机，平均每个CPU利用率在60％以上。如果这里显示CPU利用率100％，则很有可能程序里写了一个死循环。这些参数的含义，可以对比下表：

 us

用户空间占用CPU百分比

1.0% sy

内核空间占用CPU百分比

0.0% ni

用户进程空间内改变过优先级的进程占用CPU百分比

98.7% id

空闲CPU百分比

0.0% wa

等待输入输出的CPU时间百分比

3: 使用Top的交互命令H查看每个线程的性能信息。

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 31558 admin 15 0 5351m 4.0g 49m S 12.2 54.0 10:08.31 java
 31561 admin 15 0 5351m 4.0g 49m R 12.2 54.0 9:45.43 java
 31626 admin 15 0 5351m 4.0g 49m S 11.9 54.0 13:50.21 java
 31559 admin 15 0 5351m 4.0g 49m S 10.9 54.0 5:34.67 java
 31612 admin 15 0 5351m 4.0g 49m S 10.6 54.0 8:42.77 java
 31555 admin 15 0 5351m 4.0g 49m S 10.3 54.0 13:00.55 java
 31630 admin 15 0 5351m 4.0g 49m R 10.3 54.0 4:00.75 java
 31646 admin 15 0 5351m 4.0g 49m S 10.3 54.0 3:19.92 java
 31653 admin 15 0 5351m 4.0g 49m S 10.3 54.0 8:52.90 java
 31607 admin 15 0 5351m 4.0g 49m S 9.9 54.0 14:37.82 java

在这里可能会出现三种情况：

  1. 第一种情况，某个线程一直CPU利用率100％，则说明是这个线程有可能有死循环，那么请记住这个PID。
  2. 第二种情况，某个线程一直在TOP十的位置，这说明这个线程可能有性能问题。
  3. 第三种情况，CPU利用率TOP几的线程在不停变化，说明并不是由某一个线程导致CPU偏高。

如果是第一种情况，也有可能是GC造成，我们可以用jstat命令看下GC情况,看看是不是因为持久代或年老代满了，产生Full GC，导致CPU利用率持续飙高，命令如下。

sudo /opt/java/bin/jstat -gcutil 31177 1000 5
 S0 S1 E O P YGC YGCT FGC FGCT GCT
 0.00 1.27 61.30 55.57 59.98 16040 143.775 30 77.692 221.467
 0.00 1.27 95.77 55.57 59.98 16040 143.775 30 77.692 221.467
 1.37 0.00 33.21 55.57 59.98 16041 143.781 30 77.692 221.474
 1.37 0.00 74.96 55.57 59.98 16041 143.781 30 77.692 221.474
 0.00 1.59 22.14 55.57 59.98 16042 143.789 30 77.692 221.481

我们还可以把线程Dump下来，看看究竟是哪个线程，执行什么代码造成的CPU利用率高。执行以下命令，把线程dump到文件dump17里。

sudo -u admin /opt/java/bin/jstack  31177 > /home/tengfei.fangtf/dump17

dump出来内容的类似下面这段：

"http-0.0.0.0-7001-97" daemon prio=10 tid=0x000000004f6a8000 nid=0x555e in Object.wait() [0x0000000052423000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on  (a org.apache.tomcat.util.net.AprEndpoint$Worker)
        at java.lang.Object.wait(Object.java:485)
        at org.apache.tomcat.util.net.AprEndpoint$Worker.await(AprEndpoint.java:1464)
        - locked  (a org.apache.tomcat.util.net.AprEndpoint$Worker)
        at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1489)
        at java.lang.Thread.run(Thread.java:662)

dump出来的线程ID（nid）是十六进制的，而我们用TOP命令看到的线程ID是10进制的，所以我们要printf命令转换一下进制。然后用16进制的ID去dump里找到对应的线程。

 
printf "%x\n" 31558
 输出：7b46

优化实战

1：查看下TCP连接状态，建立了800多个连接，需要尽量降低ESTABLISHED。

 
[tengfei.fangtf@ifeve ~]$ netstat -nat | awk '{print $6}' | sort | uniq -c | sort -n
 1 established)
 1 Foreign
 3 CLOSE_WAIT
 7 CLOSING
 14 FIN_WAIT2
 25 LISTEN
 39 LAST_ACK
 609 FIN_WAIT1
 882 ESTABLISHED
 10222 TIME_WAIT

2：用jstack dump看看这些线程都在做什么。

sudo -u admin /opt/ifeve/java/bin/jstack 31177 > /home/tengfei.fangtf/dump17

3：统计下所有线程分别处于什么状态，发现大量线程处于WAITING(onobjectmonitor)状态

[tengfei.fangtf@ifeve ~]$ grep java.lang.Thread.State dump17 | awk '{print $2$3$4$5}' | sort | uniq -c
 39 RUNNABLE
 21 TIMED_WAITING(onobjectmonitor)
 6 TIMED_WAITING(parking)
 51 TIMED_WAITING(sleeping)
 305 WAITING(onobjectmonitor)
 3 WAITING(parking)

4：查看处于WAITING(onobjectmonitor)的线程信息，主要是jboss的工作线程在await。

"http-0.0.0.0-7001-97" daemon prio=10 tid=0x000000004f6a8000 nid=0x555e in Object.wait() [0x0000000052423000]
 java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x00000007969b2280> (a org.apache.tomcat.util.net.AprEndpoint$Worker)
 at java.lang.Object.wait(Object.java:485)
 at org.apache.tomcat.util.net.AprEndpoint$Worker.await(AprEndpoint.java:1464)
 - locked <0x00000007969b2280> (a org.apache.tomcat.util.net.AprEndpoint$Worker)
 at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1489)
 at java.lang.Thread.run(Thread.java:662)

5：找到jboss的线程配置信息，将maxThreads降低到100

<maxThreads="250" maxHttpHeaderSize="8192"
 emptySessionPath="false" minSpareThreads="40" maxSpareThreads="75" maxPostSize="512000" protocol="HTTP/1.1"
 enableLookups="false" redirectPort="8443" acceptCount="200" bufferSize="16384"
 connectionTimeout="15000" disableUploadTimeout="false" useBodyEncodingForURI="true">

6：重启jboss，再dump线程信息，然后统计，WAITING(onobjectmonitor)的线程减少了170。

[tengfei.fangtf@ifeve ~]$ grep java.lang.Thread.State dump17 | awk '{print $2$3$4$5}' | sort | uniq -c
 44 RUNNABLE
 22 TIMED_WAITING(onobjectmonitor)
 9 TIMED_WAITING(parking)
 36 TIMED_WAITING(sleeping)
 130 WAITING(onobjectmonitor)
 1 WAITING(parking)

其他命令

  • 查看CPU信息 cat /proc/cpuinfo
  • 查看内存信息 cat /proc/meminfo
  • 查看Java线程数 ps -eLf | grep java -c
  • 查看linux系统里打开文件描述符的最大值 ulimit -u
  • 找到日志里TOP10的异常：grep ‘Exception’ /home/admin/logs/XX.log |awk -F':|,’ ‘{print $2}’|sort |uniq -c |sort -nr|head -10，找到之后可以再用-A 2 -B 2，看定位出日志的前面2行和后面两行。

（全文完）如果您喜欢此文请点赞，分享，评论。

您可能感兴趣的文章

相关 [线上 性能 问题] 推荐：

线上性能问题初步排查方法

- - 并发编程网 - ifeve.com
有时候有很多问题只有在线上或者预发环境才能发现，而线上又不能Debug，所以线上问题定位就只能看日志，系统状态和Dump线程，本文只是简单的介绍一些常用的工具，帮助定位线上问题. 1: 首先使用TOP命令查看每个进程的情况，显示如下：. 我们的程序是Java应用，所以只需要关注COMMAND是Java的性能数据，COMMAND表示启动当前进程的命令，在Java进程这一行里可以看到CPU利用率是300％，不用担心，这个是当前机器所有核加在一起的CPU利用率.

不改一行代码定位线上性能问题

- - crossoverJie's Blog
最近时运不佳，几乎天天被线上问题骚扰. 前几天刚解决了一个 HashSet 的并发问题，周六又来了一个性能问题. 我们提供出去的一个 OpenAPI 反应时快时慢，快的时候几十毫秒，慢的时候几秒钟才响应. 由于这种也不是业务问题，不能直接定位. 所以尝试在测试环境复现，但遗憾的测试环境贼快. 中途有抱着侥幸心里让运维查看了 Nginx 里 OpenAPI 的响应时间，想把锅扔给网络.

Exception性能问题

- - 非技术 - ITeye博客
   1.从Exception往上介绍相关结构、代码.     class Exception里面没有什么新鲜东西，它继承自class Throwable，接下来我们看一下Throwable的结构，在它的构造函数中调用了fillInStackTrace这个函数. 接下来我们看看这个函数干了些什么.     fillInStackTrace函数的声明为.

redis 性能问题查找

- - 开源软件 - ITeye博客
          使用redis作为数据库时，系统出现少量超时，通过日志信息发现，超时发生在bgsave时. bgsave命令会fork一个子进程，子进程会将redis数据库信息dump到rdb文件中. 因此不能确定使用bgsave命令时，是fork一个子进程引起超时，还是dump文件时与主进程的sync同步同时写磁盘引起的超时.

记一次MongoDB性能问题

- Fstone - 火丁笔记
最近忙着把一个项目从MySQL迁移到MongoDB，在导入旧数据的过程中，遇到了些许波折，犯了不少错误，但同时也学到了不少知识，遂记录下来. 公司为这个项目专门配备了几台高性能务器，清一色的双路四核超线程CPU，外加32G内存，运维人员安装好MongoDB后，就交我手里了，我习惯于在使用新服务器前先看看相关日志，了解一下基本情况，当我浏览MongoDB日志时，发现一些警告信息：.

复合索引性能问题初探

- - CSDN博客推荐文章
在《品悟性能优化》一书，4.4.3章节里介绍了复合索引的两个特点：前缀性，可选性. 何为前缀性，该书阐述为排除skip scan index的情况，约束条件如果不包含复合索引的第一列，则该复合索引不会被用到；何为可选性，该书阐述为字段值越多，可选性越强，定位记录越少，查询效率越高. 即查询返回记录少的列应该放在复合索引的前面.

记一次HDFS性能问题排查

- - IT瘾-geek
就最近现网读写HDFS时，阶段性比较慢，也不是一直都比较慢，慢的时候读取一次需要20秒左右，一般毫秒级就可以返回. 这种表现第一印象就是JVM GC导致的吧. jstat -gcutil [pid] [ []],(悲哀啊，伟大的华为不让内网对外发布文章，这篇文章只能在家里写，就不可以图文并茂了，sorry)，发现每次fullGC都不会超过秒，都是毫秒级.

[JavaEE - JPA] 性能优化: 如何定位性能问题

- - CSDN博客编程语言推荐文章
要想解决性能问题，首先得要有办法定位问题，明白问题究竟是什么. 本来JPA的存在目的就是为了让开发人员能够更少地直接操作SQL，但是由于业务自身有其复杂性，如果开发人员不老练，没有踩过许许多多形形色色的坑，是很难写出高质量的JPA代码的，这也是为什么很多人说Hibernate(JPA)入门容易，精通难.

线上存储服务崩溃问题分析记录

- - codedump
上周我们的存储服务在某个线上项目频繁出现崩溃，花了几天的时间来查找解决该问题. 由于问题在线上发生，较难重现，首先想到的是能不能加上更多的信息，在问题出现时提供更多的解决思路. 首先，我们的代码里，在捕获到进程退出的信号比如SIGABRT、SIGSEGV、SIGILL等信号时，会打印出主线程的堆栈，用于帮助我们发现问题.

一次线上问题排查所引发的思考

- - crossoverJie's Blog
之前或多或少分享过一些 内存模型、 对象创建之类的内容，其实大部分人看完都是懵懵懂懂，也不知道这些的实际意义. 直到有一天你会碰到线上奇奇怪怪的问题，如：. 线程执行一个任务迟迟没有返回，应用假死. 接口响应缓慢，甚至请求超时. 这类问题并不像一个空指针、数组越界这样明显好查，这时就需要刚才提到的内存模型、对象创建、线程等相关知识结合在一起来排查问题了.