Java虚拟机(五):性能监控和分析工具

1 概述

在之前的文章,我们了解了Java内存布局、内存模型、对象模型和垃圾回收的知识。在实际生产中,绝大多数Java开发者都不会参与到JVM的开发中,那我们为什么要理解JVM呢?因为我们要排查、解决生产中出现的问题,在理解了理论知识的基础上,使用一些辅助的工具,才能更快、更准的定位问题,并且更好的解决问题。所以,接下来我们一起讨论一下一些常见的性能监控和分析工具。

2 JDK自带的工具

JDK自带了很多优秀,使用简单的工具,例如Jps,Jconsole,Jstat,Jstack等,都能在JDK目录下的bin目录找到,windows下的是.exe可执行文件,在unix系系统下的是.sh脚本文件,可以直接用vim打开。

笔者使用的windows操作系统,下面的相关工具的使用都是在windows下进行的,可能和unix系统有些许差异。

2.1 Jps

Jps即Java Process Status Tool的简称,从名称可以看到,应该是类似进程管理器的东西,实际上差不多,但是从功能上来看,还不足以称做“管理器”,因为Jps没有提供关闭,杀死进程等功能,仅仅提供了查看Java虚拟机进程的功能。

Jps的命令格式如下所示:

usage: jps [-help]
       jps [-q] [-mlvV] [<hostid>]
Definitions:
    <hostid>:      <hostname>[:<port>]

试着执行一下:

10320 sun.tools.jps.Jps
8756 org.jetbrains.jps.cmdline.Launcher
11288
2572 org/netbeans/Main

最前面的是虚拟机进程号,这个比较重要,因为后面的各种工具要连接的时候都需要知道虚拟机进程号,所以一般Jps除了查看当前有哪些进程之外,还有一个目的就是获取进程号,通过-l参数列出主类,可以知道该进程是由哪个主类(含有main的类)启动的。

上图是options的可选项,大家试试就知道了,比较简单,就不再赘述了。

2.2 Jstat

Jstat是用于监视虚拟机各种状态信息的命令行工具,包括类加载,GC,内存等信息,没有提供GUI界面。其格式如下所示:

invalid argument count
Usage: jstat -help|-options
       jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]

Definitions:
  <option>      An option reported by the -options option
  <vmid>        Virtual Machine Identifier. A vmid takes the following form:
                     <lvmid>[@<hostname>[:<port>]]
                Where <lvmid> is the local vm identifier for the target
                Java virtual machine, typically a process id; <hostname> is
                the name of the host running the target Java virtual machine;
                and <port> is the port number for the rmiregistry on the
                target host. See the jvmstat documentation for a more complete
                description of the Virtual Machine Identifier.
  <lines>       Number of samples between header lines.
  <interval>    Sampling interval. The following forms are allowed:
                    <n>["ms"|"s"]
                Where <n> is an integer and the suffix specifies the units as
                milliseconds("ms") or seconds("s"). The default units are "ms".
  <count>       Number of samples to take before terminating.
  -J<flag>      Pass <flag> directly to the runtime system.

在使用之前,我们得先用Jps获取虚拟机进程ID,我在本机上启动了一个Java进程,用Jps获取的进程ID是14220。接下来执行jstat命令:

> jstat -gcutil 14220
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00   0.00   0.00   1.04  71.42  74.38      2    0.046     1    0.002    0.048

其中S0和S1是Survivor区,E是Eden,O是Old,M是MetaSpace(Java8之后有的元空间,就是以前的方法区),CCS压缩类空间,YGC是新生代GC的次数,YGCT是新生代GC消耗的时间,FGC是Full GC的次数,FGCT是Full GC消耗的时间,GCT是GC消耗的总时间(FGCT + YGCT)。

其他主要的选项如下图所示:

2.3 Jinfo

Jinfo的作用是实时的查看和修改虚拟机的各项参数。其格式如下所示:

Usage:
    jinfo [option] <pid>
        (to connect to running process)
    jinfo [option] <executable <core>
        (to connect to a core file)
    jinfo [option] [server_id@]<remote server IP or hostname>
        (to connect to remote debug server)

where <option> is one of:
    -flag <name>         to print the value of the named VM flag
    -flag [+|-]<name>    to enable or disable the named VM flag
    -flag <name>=<value> to set the named VM flag to the given value
    -flags               to print VM flags
    -sysprops            to print Java system properties
    <no option>          to print both of the above
    -h | -help           to print this help message

主要就是-flag参数,下面是一个使用示例:

> jinfo  -flag CMSInitiantingOccupancyFraction 14220
-XX:CMSInitiatingOccupancyFraction=-1

2.4 Jmap

Jmap用于生成堆转储快照,即dump文件,除了获取dump文件,Jmap还可以查看堆,垃圾收集器等信息。其格式如下所示:

Usage:
    jmap [option] <pid>
        (to connect to running process)
    jmap [option] <executable <core>
        (to connect to a core file)
    jmap [option] [server_id@]<remote server IP or hostname>
        (to connect to remote debug server)

where <option> is one of:
    <none>               to print same info as Solaris pmap
    -heap                to print java heap summary
    -histo[:live]        to print histogram of java object heap; if the "live"
                         suboption is specified, only count live objects
    -clstats             to print class loader statistics
    -finalizerinfo       to print information on objects awaiting finalization
    -dump:<dump-options> to dump java heap in hprof binary format
                         dump-options:
                           live         dump only live objects; if not specified,
                                        all objects in the heap are dumped.
                           format=b     binary format
                           file=<file>  dump heap to <file>
                         Example: jmap -dump:live,format=b,file=heap.bin <pid>
    -F                   force. Use with -dump:<dump-options> <pid> or -histo
                         to force a heap dump or histogram when <pid> does not
                         respond. The "live" suboption is not supported
                         in this mode.
    -h | -help           to print this help message
    -J<flag>             to pass <flag> directly to the runtime system

执行如下命令:

> jmap -heap 14220
Mark Sweep Compact GC

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 104857600 (100.0MB)
   NewSize                  = 34930688 (33.3125MB)
   MaxNewSize               = 34930688 (33.3125MB)
   OldSize                  = 69926912 (66.6875MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 31457280 (30.0MB)
   used     = 0 (0.0MB)
   free     = 31457280 (30.0MB)
   0.0% used
Eden Space:
   capacity = 27983872 (26.6875MB)
   used     = 0 (0.0MB)
   free     = 27983872 (26.6875MB)
   0.0% used
From Space:
   capacity = 3473408 (3.3125MB)
   used     = 0 (0.0MB)
   free     = 3473408 (3.3125MB)
   0.0% used
To Space:
   capacity = 3473408 (3.3125MB)
   used     = 0 (0.0MB)
   free     = 3473408 (3.3125MB)
   0.0% used
tenured generation:
   capacity = 69926912 (66.6875MB)
   used     = 725560 (0.6919479370117188MB)
   free     = 69201352 (65.99555206298828MB)
   1.03759765625% used

1764 interned Strings occupying 157712 bytes.

第一行就显示了使用哪种垃圾收集器,在我这里是Mark Sweep Compact,即CMS。其他信息包含了堆的新生代,老年代的空间大小,使用量等。下图是其他的一些主要参数:

2.5 Jhat

Jhat用来配合Jmap使用的,用于分析Jmap生成的堆快照。命令格式如下所示:

Usage:  jhat [-stack <bool>] [-refs <bool>] [-port <port>] [-baseline <file>] [-debug <int>] [-version] [-h|-help] <file>

        -J<flag>          Pass <flag> directly to the runtime system. For
                          example, -J-mx512m to use a maximum heap size of 512MB
        -stack false:     Turn off tracking object allocation call stack.
        -refs false:      Turn off tracking of references to objects
        -port <port>:     Set the port for the HTTP server.  Defaults to 7000
        -exclude <file>:  Specify a file that lists data members that should
                          be excluded from the reachableFrom query.
        -baseline <file>: Specify a baseline object dump.  Objects in
                          both heap dumps with the same ID and same class will
                          be marked as not being "new".
        -debug <int>:     Set debug level.
                            0:  No debug output
                            1:  Debug hprof file parsing
                            2:  Debug hprof file parsing, no server
        -version          Report version number
        -h|-help          Print this help and exit
        <file>            The file to read

For a dump file that contains multiple heap dumps,
you may specify which dump in the file
by appending "#<number>" to the file name, i.e. "foo.hprof#3".

All boolean options default to "true"

这个是提供GUI界面的,不过一般不会用在生产环境,一个原因分析dump文件时一件非常消耗资源的事,如果在生产环境上做了可能会导致一些资源方面的问题,另一个原因是Jhat分析的内容比较简陋,有用信息比较少。

在使用之前,我们得先使用Jmap生成一份dump文件,如下所示:

> jmap -dump:format=b,file=test.bin 14220
Dumping heap to C:\Users\72419\Desktop\test.bin ...
Heap dump file created

然后使用jhat读入该文件,并分析:

> jhat test.bin
Reading from test.bin...
Dump file created Mon Sep 24 14:50:11 CST 2018
Snapshot read, resolving...
Resolving 10303 objects...
Chasing references, expect 2 dots..
Eliminating duplicate references..
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.

从日志可以看到,Jhat启动了一个HTTP服务,在7000端口监听,启动浏览器,输入http://localhost:7000/ 即可进入GUI界面。如下所示:

点击进去慢慢探索吧。

2.6 Jstack

Jstack用于生成虚拟机当前时刻的线程快照,生成该快照的目的是为了定位线程问题,例如死锁,活锁,死循环或者请求外部资源导致的长时间等待等,通过分析快照的堆栈信息,就可以快速定位代码中的哪个类,哪个方法,甚至哪行出现了问题。下面是我写的一个死锁程序,启动之后,我们通过Jstack来查看线程快照,然后定位问题:

public class DeadLockTest {

    static class DeadLock extends Thread {

        private final String lockA;
        private final String lockB;

        public DeadLock(String lockA, String lockB) {
            this.lockA = lockA;
            this.lockB = lockB;
        }

        @Override
        public void run() {
            synchronized (lockA) {
                System.out.println(Thread.currentThread().getName() + " get lock " + lockA);
                try {
                    Thread.sleep(500);   //停顿一下,让另一个线程运行
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                synchronized (lockB) {
                    System.out.println(Thread.currentThread().getName() + " get lock " + lockB);
                }
            }
        }
    }

    public static void main(String[] args) {
        String lockA = "lockA";
        String lockB = "lockB";
        Thread thread1 = new DeadLock(lockA, lockB);
        Thread thread2 = new DeadLock(lockB, lockA);

        thread1.start();
        thread2.start();

    }
}

简单解释一下程序,启动两个线程,这两个线程都要获取A和B两把锁,但是获取的顺序不同。这样就导致了线程1获取了A锁,等待B锁,但是B锁已经被线程2获取了,并且线程2也在等待A锁,最终导致他们都无法获取到锁,也就无法继续执行,导致了死锁。

使用Jstack来生成快照尝试分析:

> jstack -l 12432
......
"Thread-1" #12 prio=5 os_prio=0 tid=0x00000000195bd000 nid=0x5e90 waiting for monitor entry [0x000000001a20f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at top.yeonon.ch10.DeadLockTest$DeadLock.run(DeadLockTest.java:29)
        - waiting to lock <0x00000000d5fc0588> (a java.lang.String)
        - locked <0x00000000d5fc05c0> (a java.lang.String)

   Locked ownable synchronizers:
        - None

"Thread-0" #11 prio=5 os_prio=0 tid=0x00000000195ba000 nid=0x5ed4 waiting for monitor entry [0x000000001a10f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at top.yeonon.ch10.DeadLockTest$DeadLock.run(DeadLockTest.java:29)
        - waiting to lock <0x00000000d5fc05c0> (a java.lang.String)
        - locked <0x00000000d5fc0588> (a java.lang.String)

   Locked ownable synchronizers:
        - None
......
Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x000000000357ccf8 (object 0x00000000d5fc0588, a java.lang.String),
  which is held by "Thread-0"
"Thread-0":
  waiting to lock monitor 0x000000000357b858 (object 0x00000000d5fc05c0, a java.lang.String),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
        at top.yeonon.ch10.DeadLockTest$DeadLock.run(DeadLockTest.java:29)
        - waiting to lock <0x00000000d5fc0588> (a java.lang.String)
        - locked <0x00000000d5fc05c0> (a java.lang.String)
"Thread-0":
        at top.yeonon.ch10.DeadLockTest$DeadLock.run(DeadLockTest.java:29)
        - waiting to lock <0x00000000d5fc05c0> (a java.lang.String)
        - locked <0x00000000d5fc0588> (a java.lang.String)

Found 1 deadlock.

信息比较多,而且我已经省略了一些,主要看Found one Java-level deadlock后面的内容吧,这说明Jstack发现了一个死锁,并且将死锁相关的线程堆栈信息打印出来了,从上面可以看到“Thread-1”线程拿到了<0x00000000d5fc05c0>锁,正在等待 <0x00000000d5fc0588>锁,“Thread-0”拿着<0x00000000d5fc0588>锁,正在等待 <0x00000000d5fc05c0>,显然就是死锁了,同时看堆栈可以看到问题发生在DeadLockTest.java:29,即该类的29行出现问题(虽然这个值不一定完全对应源码位置,但基本相差不大,也算是有用的信息),接下来就是到源码相应的位置去分析代码了。

Jstack的其他主要参数选项如下所示:

2.7 Jconsole

Jconsole是一个可视化工具,命令行输入jconsole,打开之后就看到GUI界面了,界面大致如下所示:

每个标签的意义也比较明显,可以试着自己玩玩,比较简单,不再赘述。

我之前有一篇文章中简单提到过一些Jconsole的使用,可以去看看。理解Java内存泄露

3 第三方工具

3.1 VisualVM

VisualVM是一款非常强大的性能监控和分析工具,集合了多项功能,包括导出dump文件,分析dump文件,监控线程状态,监控虚拟机各项状态指标等,还提供了诸多丰富的插件给用户使用。

使用之前得先去官网下载,下载安装、简单使用就不多说了,网上有很多文章介绍,本文只讨论一个插件:BTrace。

Btrace是一个很有趣的插件,他可以在运行时插入一些调试代码,利用这个插件我们就可以实现不停止程序就能进行简单调试的功能。先写一些代码用来测试:

public class BTraceTest {

    public int add(int a, int b) {
        return a + b;
    }

    public static void main(String[] args) {
        BTraceTest bTraceTest = new BTraceTest();
        Scanner scanner = new Scanner(System.in);
        for (int i = 0; i < 10; i++) {
            scanner.nextLine();
            int a = (int) Math.round(Math.random() * 1000);
            int b = (int) Math.round(Math.random() * 1000);
            System.out.println(bTraceTest.add(a, b));
        }
    }
}

就是加分运算而已,使用Scanner是为了慢慢的看日志变化,感受BTrace的功能。启动程序之后,到VisualVM的侧边栏看看Local选项,点击后选中刚刚运行的程序,如下所示:

右键点击,选中Trace application,之后可以在右边看到一个编译器,可以在里面编写Java代码,这些代码就是用于跟踪调试源代码的,如下图所示:

加入如下代码:

/* BTrace Script Template */
import com.sun.btrace.annotations.*;
import static com.sun.btrace.BTraceUtils.*;

@BTrace
public class TracingScript {
    /* put your code here */
    @OnMethod(clazz="top.yeonon.ch10.BTraceTest", method="add", location=@Location(Kind.RETURN))
    public static void func(@Self top.yeonon.ch10.BTraceTest instance, int a, int b, @Return int result) {
        println("调用堆栈:");
        jstack();
        println(strcat("方法参数A:",str(a)));    
        println(strcat("方法参数B:",str(b)));    
        println(strcat("返回值result:",str(result)));    
    }
}

然后点击上方的start按钮,启动BTrace,等看到下方控制台中出现Done字样的时候,我们就到IDE里随便输入字符(多输入几次),然后再回到VisualVM控制台中看看结果,大致内容如下:

这就完成了一次代码动态调试,是不是感觉很屌。BTrace还有很多其他功能,详细可以到网上去搜索。

4 小结

对虚拟机进行监控,调优以及出现问题的时候定位问题,解决问题是我们学习Java虚拟机的目的,在掌握了虚拟机相关的知识理论之后再利用辅助工具,才能更好的发现问题,解决问题。本文介绍了诸多工具,每种工具都有优点和不足,了解这些工具的特性,多多尝试使用,才能更好的掌握它们。

5 参考资料

《深入理解Java虚拟机》

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 211,884评论 6 492
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 90,347评论 3 385
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 157,435评论 0 348
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 56,509评论 1 284
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 65,611评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 49,837评论 1 290
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,987评论 3 408
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,730评论 0 267
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,194评论 1 303
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,525评论 2 327
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,664评论 1 340
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,334评论 4 330
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,944评论 3 313
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,764评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,997评论 1 266
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,389评论 2 360
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,554评论 2 349

推荐阅读更多精彩内容

  • 参考博客:https://blog.csdn.net/yx0628/article/details/3009121...
    susu2016阅读 634评论 1 3
  • 泛黄的照片,落寞的街景。坐在床角的我脑海里浮现出一幅幅扣人心弦的的画面。灵魂已不受控制,仿佛被一种不知名的东西所牵...
    柚萫阅读 237评论 6 4
  • 今日体验:早上一辆现代胜达菲进场 客户反应车跑着跑着熄火 用电脑度数据流加上互相码 判断氧传感器有问题 检查发现 ...
    酷酷的峰666阅读 223评论 0 0
  • 自从无意惊觉于“螳螂捕蝉黄雀在后”背后当局者与旁观者视角的自由精妙转换 猫眼一词便引申为各大网站的惯用昵称 时常作...
    猫眼有态度阅读 219评论 0 0