JVM学习(1)-读懂虚拟机日志

一.跟踪调试参数

1.跟踪垃圾回收:

测试代码:

public class NewSizeDemo {
    public static void main(String[] args) {
        byte[] b=null;
        for(int i=0;i<10;i++){
            b=new byte[1*1024*1024];
        }
    }
}
  1. 打印回收信息:-server -Xmx10m -Xms5m -XX:+PrintGC
    -server :设置JVM使用server模式。64位JDK默认启动该模式。
    -Xmx10m:
    XX:+PrintGC表示只要遇到GC就打印日志,日志如下:
    [GC (Allocation Failure) 1024K->464K(5632K), 0.0009867 secs]
    [GC (Allocation Failure) 7037K->6616K(8704K), 0.0008138 secs]
    [GC (Allocation Failure) 6616K->6624K(8704K), 0.0005095 secs]
    [Full GC (Allocation Failure) 6624K->1389K(5632K), 0.0059130 secs]
    日志分析:

GC:垃圾回收。
Full GC:收集整个堆,包括young gen、old gen、perm gen(如果存在的话)等所有部分的模式。
Allocation Failure:引起垃圾回收的原因. 本次GC是因为年轻代中没有任何合适的区域能够存放需要分配的数据结构而触发的。

第一行,gc前堆空间使用量为1024k,GC后,堆使用量为464K,当前可使用的对空间为(5632K),0.0009867 secs是回收用的时间。

  1. 打印更详细信息,-server -Xmx10m -Xms5m -XX:+PrintGCDetail
    日志如下:

第1行:[GC (Allocation Failure) [PSYoungGen: 1024K->464K(1536K)] 1024K->464K(5632K), 0.0007313 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
第2行:[GC (Allocation Failure) [PSYoungGen: 893K->496K(1536K)] 7037K->6648K(8704K), 0.0010580 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]
第3行:[GC (Allocation Failure) [PSYoungGen: 496K->432K(1536K)] 6648K->6584K(8704K), 0.0006839 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
第4行:[Full GC (Allocation Failure) [PSYoungGen: 432K->0K(1536K)] [ParOldGen: 6152K->1389K(4096K)] 6584K->1389K(5632K), [Metaspace: 3071K->3071K(1056768K)], 0.0044727 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

Heap
PSYoungGen total 1536K, used 61K [0x00000007bfd00000, 0x00000007c0000000, 0x00000007c0000000)
eden space 1024K, 6% used [0x00000007bfd00000,0x00000007bfd0f760,0x00000007bfe00000)
from space 512K, 0% used [0x00000007bfe00000,0x00000007bfe00000,0x00000007bfe80000)
to space 512K, 0% used [0x00000007bff80000,0x00000007bff80000,0x00000007c0000000)
ParOldGen total 5632K, used 5485K [0x00000007bf600000, 0x00000007bfb80000, 0x00000007bfd00000)
object space 5632K, 97% used [0x00000007bf600000,0x00000007bfb5b688,0x00000007bfb80000)
Metaspace used 3083K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 339K, capacity 388K, committed 512K, reserved 1048576K

日志分析:
对于第1行的日志,这是个对年轻代的回收。
PSYoungGen:指对于年轻代的回收。
PSYoungGen: 1024K->464K(1536K)] 1024K->464K(5632K):
Young GC前年轻代从1024K到464K,年轻代可使用1536K,整个堆的占用从1024K到464K,总的堆可以5632K。说明老年代没有分配空间。

对于第4行的日志,这是个full gc对PSYoungGen,ParOldGen和Metaspace的使用情况,跟新生代相同。
[Times: user=0.01 sys=0.00, real=0.01 secs] :
指GC回收的时间:user 是用户态消耗的CPU时间,sys 是内核态消耗的CPU时间,而real 是操作从开始到结束的时间(包括各种非计算的等待耗时,如I/O、线程阻塞),当系统有多CPU(多核)情况下,多线程会叠加这些CPU时间,所有user 或 sys 时间超过real是正常的;

显示jvm在退出前打印堆的各个区的使用情况:
PSYoungGen total 1536K, used 61K [0x00000007bfd00000, 0x00000007c0000000, 0x00000007c0000000)
新生代:1536K
3个16进制数字分别表示:新生代的下界,当前上界和新生代的上界。
新生代的上界-下界:
00000007c0000000-00000007bfd00000= 33285996544-33282850816 =3145728/1024=3072k。同时eden,from,to也有对于的16值区间,正好印证整个新生代的上界-下界的区间。
但是eden+from+to=2048k 两者差额以后再说。

  1. 显示GC前后的堆信息:-XX:+PrintHeapAtGC:
    能够很好的观察GC对于堆空间的影响。
    {Heap before GC invocations=1 (full 0):
    PSYoungGen total 1536K, used 1024K [0x00000007bfd00000, 0x00000007bff00000, 0x00000007c0000000)
    eden space 1024K, 100% used
    ...
    class space used 287K, capacity 386K, committed 512K, reserved 1048576K
    Heap after GC invocations=1 (full 0):
    PSYoungGen total 1536K, used 400K [0x00000007bfd00000, 0x00000007bff00000, 0x00000007c0000000)
    ...
    Metaspace used 2612K, capacity 4490K, committed 4864K, reserved 1056768K
    class space used 287K, capacity 386K, committed 512K, reserved 1048576K
    }

  2. 分析GC发生的实际,打印CG发生的时间戳
    -XX:+PrintGCTimeStamps:
    0.271: [GC (Allocation Failure) 1024K->464K(5632K), 0.0112903 secs]
    0.313: [GC (Allocation Failure) 7038K->6616K(9728K), 0.0008725 secs]
    0.315: [GC (Allocation Failure) -- 7681K->7681K(9728K), 0.0013294 secs]
    0.316: [Full GC (Ergonomics) 7681K->1389K(6656K), 0.0144772 secs]
    在jvm启动后分别在0.271,0.313,0.315,0.316经历了4次GC。

  3. 打印程序的执行的时间 -XX:+PrintGCApplicationConcurrentTime
    日志:
    Application time: 0.0022902 seconds

  4. 打印程序的执行的时间 -XX:+PrintGCApplicationConcurrentTime
    日志:
    Application time: 0.0022902 seconds

7.打印GC停顿时间 -XX:+PrintGCApplicationStoppedTime
Total time for which application threads were stopped: 0.0073859 seconds, Stopping threads took: 0.0000160 seconds

8.跟踪软引用,弱引用,虚引用和Finalize队列,可以打开-XX:+PrintReferenceGC开关:
[GC (Allocation Failure) [ParNew[SoftReference, 0 refs, 0.0001451 secs][WeakReference, 8 refs, 0.0001191 secs][FinalReference, 0 refs, 0.0001226 secs][PhantomReference, 0 refs, 0 refs, 0.0001833 secs][JNI Weak Reference

, 0.0111948 secs]: 81926K->6K(92160K), 0.0141540 secs] 82337K->417K(296960K), 0.0145097 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

9.GC以日志文件输出:-Xloggc:log/gc.log

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