Jstack分析高负载的Java线程

http://www.badnotes.com/2014/11/02/jstack/

1. top查看高负载的进程

查看进程

top

  • top - 05:48:13 up 299 days, 21:59, 2 users, load average: 9.00, 8.99, 9.03
  • Tasks: 78 total, 1 running, 77 sleeping, 0 stopped, 0 zombie
  • Cpu(s): 3.4%us, 0.1%sy, 0.0%ni, 96.2%id, 0.3%wa, 0.0%hi, 0.0%si, 0.0%st
  • Mem: 35062388k total, 34768556k used, 293832k free, 314468k buffers

  • Swap: 0k total, 0k used, 0k free, 27836352k cached

  • PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
  • 31327 root 20 0 7506m 4.8g 10m S 398.8 14.3 14580:05 java

查看线程

top -Hp 31327 (top -p 31327,再按shift+h)

  • top - 05:52:15 up 299 days, 22:03, 2 users, load average: 9.07, 9.00, 9.04
  • Tasks: 175 total, 9 running, 166 sleeping, 0 stopped, 0 zombie
  • Cpu(s): 3.4%us, 0.1%sy, 0.0%ni, 96.2%id, 0.3%wa, 0.0%hi, 0.0%si, 0.0%st
  • Mem: 35062388k total, 34768980k used, 293408k free, 314468k buffers

  • Swap: 0k total, 0k used, 0k free, 27836388k cached

  • PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
  • 31377 root 20 0 7506m 4.8g 10m R 49.5 14.3 1603:05 java
  • 31387 root 20 0 7506m 4.8g 10m R 49.5 14.3 1639:41 java
  • 31378 root 20 0 7506m 4.8g 10m R 45.5 14.3 1604:03 java
  • 31381 root 20 0 7506m 4.8g 10m R 43.5 14.3 1614:25 java
  • 31385 root 20 0 7506m 4.8g 10m R 43.5 14.3 1643:05 java
  • 31389 root 20 0 7506m 4.8g 10m R 43.5 14.3 1605:30 java
  • 31375 root 20 0 7506m 4.8g 10m R 41.5 14.3 1600:50 java
  • 31376 root 20 0 7506m 4.8g 10m R 41.5 14.3 1602:16 java
  • 22359 root 20 0 7506m 4.8g 10m R 39.6 14.3 1623:17 java

2. jstack 查看java 堆栈信息

直接打印

jstack 31327 grep -A 10 7a91 (线程16进制pid)

导出到文件

jstack 31327 > jstack_info.log


 
  1. "http-bio-18080-exec-11" daemon prio=10 tid=0x00007f50b028e800 nid=0x5757 runnable [0x00007f50936eb000]
  2. "http-bio-18080-exec-9" daemon prio=10 tid=0x00007f50b02a5000 nid=0x7a9d runnable [0x00007f512d6b5000]
  3. "http-bio-18080-exec-8" daemon prio=10 tid=0x00007f50b02a3800 nid=0x7a9b runnable [0x00007f512d9e3000]
  4. "http-bio-18080-exec-7" daemon prio=10 tid=0x00007f50b0011000 nid=0x7a99 runnable [0x00007f512dc88000]
  5. "http-bio-18080-exec-5" daemon prio=10 tid=0x00007f50b000e000 nid=0x7a95 runnable [0x00007f512dd8a000]
  6. "http-bio-18080-exec-4" daemon prio=10 tid=0x00007f50b000c000 nid=0x7a92 runnable [0x00007f512de0b000]
  7. "http-bio-18080-exec-3" daemon prio=10 tid=0x00007f50b000a000 nid=0x7a91 runnable [0x00007f512de8c000]
  8. "http-bio-18080-exec-2" daemon prio=10 tid=0x00007f50b0006800 nid=0x7a90 runnable [0x00007f512df0d000]
  9. "http-bio-18080-exec-1" daemon prio=10 tid=0x00007f50b0005000 nid=0x7a8f runnable [0x00007f512ea67000]

可以看到这些线程都一直挂在程序的某一行，多半是这里发生了死锁


 
  1. "http-bio-18080-exec-8" daemon prio=10 tid=0x00007f50b02a3800 nid=0x7a9b runnable [0x00007f512d9e3000]
  2. java.lang.Thread.State: RUNNABLE
  3. at java.util.HashMap.getEntry(HashMap.java:364)
  4. at java.util.HashMap.containsKey(HashMap.java:352)
  5. at com.xxx.xxx.dao.xxxHelper.getInfo(xxxHelper.java:108)

3. 然后去分析源代码

HashMap 是会出现死锁的,改为ConcurrentHashMap问题解决

4. 线程状态

  • Deadlock – 死锁 
  • Runnable – 执行中 
  • Suspended – 暂停 
  • Blocked – 阻塞 
  • Parked – 停止 
  • Waiting on condition – 等待资源 
  • Waiting on monitor entry – 等待获取监视器 
  • Object.wait() 或 TIMED_WAITING – 对象等待中

 

记一次java性能问题定位

http://hongweiyi.com/2013/10/once-java-profiling/

 

记一次java性能问题定位 

1、前言

前一段时间检查集群状态时，发现某部分机器的load较高，故登录服务器查看，某几个java进程的cpu使用率为1000%，没见过这么高的cpu时间，顿时就长见识了！长完见识问题还是要解决的，故本文记录下问题定位的过程。

 

2、定位流程

2.1 定位问题进程

top命令可以简单定位进程pid，如下：

Image

jps -vm | grep 15195 可以查看java进程的参数或者日志地址等，如果没有显示参数的话，可以cd到/proc/15195/cwd目录，该目录便是进程的运行目录。

2.2 查看日志

常规做法就是查看日志了，但是扫了几遍日志也没发现问题，因为这个进程这几天的请求都不是很多，难道是线程空转了？

2.3 定位问题线程

既然日志没有发现异常，那只是通过查看进程内部发现问题了。man top可以看到top命令的详细信息，-H则是线程开关，传入该参数的话，top界面会显示所有单独的线程列表。

Image(1)

不看不知道，一看吓一跳啊，cpu跑满的线程挺多的，第一列便是他们的线程id。

2.4 Thread dump

拿到异常的线程id后，便可以将该进程的线程栈全部输出了，用到的工具是jstack。

jstack 15195 > jstack.15195.dump

Image(2)

快速搜索的话，可以直接拿pid转换成16进程定位，当然，也可以慢慢看那些线程处于RUNNABLE状态，不过定位问题较慢。

通过查询异常线程pid，发现所有的都是Parallel GC Threads，实在是太奇怪了。

2.5 查看gc状态

jstat -gc 15195 获得当前进程的gc状态，会发现该线程在不断的进行FullGC操作：

Image(3)

Image(4)

短短几分钟，就FGC了28次！初步定位问题为FGC问题。

注：用jstat -gcutil $PID $INTERVAL $TIMES查询可能会更直接，我查到这里应用被停止了，就木有现场了。

3、问题解决

现在出现的问题就是表现在了full gc次数频繁，从上面的应用而言，可以发现PU(PermGen Usage)占用非常高，约为95.7%。由于Perm代过高，且CMS GC无法回收掉Perm区内容，而导致频繁GC。

CMS GC与普通的STW Full GC不同，不会暂停应用，但是会导致CPU使用率非常高。

解决方法有两种：1）提高Perm区大小，-XX:PermSize -XX:MaxPermSize，2）关掉Perm区收集机制，取消-XX:+CMSClassUnloadingEnabled。

 

http://www.cnblogs.com/mazj611/p/3481610.html

 

 

Jstat在分析java的内存GC时的应用

jstat工具特别强大，有众多的可选项，详细查看堆内各个部分的使用量，以及加载类的数量。使用时，需加上查看进程的进程id，和所选参数。

执行：cd $JAVA_HOME/bin中执行jstat，注意jstat后一定要跟参数。

各个参数的意义。 

  •     jstat -class pid:显示加载class的数量，及所占空间等信息。  
  •     jstat -compiler pid:显示VM实时编译的数量等信息。  
  •     jstat -gc pid:可以显示gc的信息，查看gc的次数，及时间。其中最后五项，分别是young gc的次数，young gc的时间，full gc的次数，full gc的时间，gc的总时间。  
  •     jstat -gccapacity:可以显示，VM内存中三代（young,old,perm）对象的使用和占用大小，如：PGCMN显示的是最小perm的内存使用量，PGCMX显示的是perm的内存最大使用量，PGC是当前新生成的perm内存占用量，PC是但前perm内存占用量。其他的可以根据这个类推， OC是old内纯的占用量。  
  •     jstat -gcnew pid:new对象的信息。  
  •     jstat -gcnewcapacity pid:new对象的信息及其占用量。  
  •     jstat -gcold pid:old对象的信息。  
  •     jstat -gcoldcapacity pid:old对象的信息及其占用量。  
  •     jstat -gcpermcapacity pid: perm对象的信息及其占用量。  
  •     jstat -util pid:统计gc信息统计。  
  •     jstat -printcompilation pid:当前VM执行的信息。  
  •     除了以上一个参数外，还可以同时加上 两个数字，如：jstat -printcompilation 3024 250 6是每250毫秒打印一次，一共打印6次，还可以加上-h3每三行显示一下标题。
  • 语法结构：    
  • Usage: jstat -help|-options    
  •        jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]    
  • 参数解释：    
  • Options — 选项，我们一般使用 -gcutil 查看gc情况比较多    
  • vmid    — VM的进程号，即当前运行的java进程号    
  • interval– 间隔时间，单位为秒或者毫秒   
  • count   — 打印次数，如果缺省则打印无数次   
  • S0  — Heap上的 Survivor space 0 区已使用空间的百分比  
  • S1  — Heap上的 Survivor space 1 区已使用空间的百分比  
  • E   — Heap上的 Eden space 区已使用空间的百分比  
  • O   — Heap上的 Old space 区已使用空间的百分比  
  • P   — Perm space 区已使用空间的百分比  
  • YGC — 从应用程序启动到采样时发生 Young GC 的次数  
  • YGCT– 从应用程序启动到采样时 Young GC 所用的时间(单位秒)  
  • FGC — 从应用程序启动到采样时发生 Full GC 的次数  
  • FGCT– 从应用程序启动到采样时 Full GC 所用的时间(单位秒)  
  • GCT — 从应用程序启动到采样时用于垃圾回收的总时间(单位秒)

如：[root@localhost bin]# jstat -gcutil 25332  1000  10     （25332是java的进程号，ps -ef | grep java）

分代概念：

分代是Java垃圾收集的一大亮点，根据对象的生命周期长短，把堆分为3个代：Young，Old和Permanent，根据不同代的特点采用不同的收集算法，扬长避短也。

Young(Nursery)，年轻代。研究表明大部分对象都是朝生暮死，随生随灭的。因此所有收集器都为年轻代选择了复制算法。

复制算法优点是只访问活跃对象，缺点是复制成本高。因为年轻代只有少量的对象能熬到垃圾收集，因此只需少量的复制成本。而且复制收集器只访问活跃对象，对那些占了最大比率的死对象视而不见，充分发挥了它遍历空间成本低的优点。

Young（年轻代）

年 轻代分三个区。一个Eden区，两个Survivor区。大部分对象在Eden区中生成。当Eden区满时，还存活的对象将被复制到Survivor区 （两个中的一个），当这个Survivor区满时，此区的存活对象将被复制到另外一个Survivor区，当这个Survivor去也满了的时候，从第一 个Survivor区复制过来的并且此时还存活的对象，将被复制“年老区(Tenured)”。需要注意，Survivor的两个区是对称的，没先后关 系，所以同一个区中可能同时存在从Eden复制过来 对象，和从前一个Survivor复制过来的对象，而复制到年老区的只有从第一个Survivor去过来的对象。而且，Survivor区总有一个是空 的。

Tenured（年老代）

年老代存放从年轻代存活的对象。一般来说年老代存放的都是生命期较长的对象。

Perm（持久代）

用 于存放静态文件，如今Java类、方法等。持久代对垃圾回收没有显著影响，但是有些应用可能动态生成或者调用一些class，例如Hibernate等， 在这种时候需要设置一个比较大的持久代空间来存放这些运行过程中新增的类。持久代大小通过-XX:MaxPermSize=进行设置。

Gc的基本概念

gc分为full gc 跟 minor gc，当每一块区满的时候都会引发gc。

Scavenge GC

一般情况下，当新对象生成，并且在Eden申请空间失败时，就触发了Scavenge GC，堆Eden区域进行GC，清除非存活对象，并且把尚且存活的对象移动到Survivor区。然后整理Survivor的两个区。

Full GC

对整个堆进行整理，包括Young、Tenured和Perm。Full GC比Scavenge GC要慢，因此应该尽可能减少Full GC。有如下原因可能导致Full GC：

Tenured被写满

Perm域被写满

System.gc()被显示调用

上一次GC之后Heap的各域分配策略动态变化

 

原文链接：https://blog.csdn.net/jiang117/article/details/48272151

 

这里有关于Perm区GC时机的深入且详细的解释，http://rednaxelafx.iteye.com/blog/1108439

CMS收集器的使用好像有很多很多的优(jiu)化(shi)点(keng)啊！

还得深入学习实践一下！