HBase GC日志，hbasegc日志


HBase依靠ZooKeeper来感知集群成员及其存活性。如果一个服务器暂停了很长时间，它将无法给ZooKeeper quorum发送心跳信息，其它服务器会认为这台服务器已死亡。这将导致master为其启动恢复进程。当该服务器脱离停顿时，它会发现它的所有租约都已失效（hbase client端每次和regionserver交互的时候，都会在服务器端生成一个租约（Lease)，租约的有效期由参数hbase.regionserver.lease.period确定），然后自杀。HBase开发团队亲切地称这个场景为Juliet Pause。

在HBase中使用默认GC，可以看到所有线程中的长时间停顿，包括Juliet Pause， 又名"GC of Death"。可以在JAVA虚拟机中开启GC日志，来帮助调试这种问题。

在hbase-env.sh中，取消以下任一注释即可开启GC日志：

# This enables basic gc logging to the .out file.
# export SERVER_GC_OPTS="-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps"

# This enables basic gc logging to its own file.
# export SERVER_GC_OPTS="-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:<FILE-PATH>"

# This enables basic GC logging to its own file with automatic log rolling. Only applies to jdk 1.6.0_34+ and 1.7.0_2+.
# export SERVER_GC_OPTS="-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:<FILE-PATH> -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=1 -XX:GCLogFileSize=512M"

# If <FILE-PATH> is not replaced, the log file(.gc) would be generated in the HBASE_LOG_DIR.



点击"Local logs"，查看gc-xxx.log日志，格式如下：

15578637.583: [GC [1 CMS-initial-mark: 12076002K(12582912K)] 18788432K(29360128K), 1.0113310 secs] [Times: user=1.01 sys=0.00, real=1.01 secs]
15578638.595: [CMS-concurrent-mark-start]
15578639.125: [CMS-concurrent-mark: 0.530/0.530 secs] [Times: user=1.61 sys=0.01, real=0.53 secs]
15578639.125: [CMS-concurrent-preclean-start]
15578639.160: [CMS-concurrent-preclean: 0.035/0.035 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
15578639.160: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 15578644.606: [CMS-concurrent-abortable-preclean: 5.446/5.446 secs] [Times: user=5.82 sys=0.07, real=5.45 secs]
15578644.607: [GC[YG occupancy: 6769031 K (16777216 K)]15578644.607: [Rescan (parallel) , 0.9756010 secs]15578645.583: [weak refs processing, 0.0000280 secs]15578645.583: [scrub string table, 0.0006370 secs] [1 CMS-remark: 12076002K(12582912K)] 18845034K(29360128K), 0.9764070 secs] [Times: user=9.52 sys=0.03, real=0.97 secs]
15578645.584: [CMS-concurrent-sweep-start]
15578645.829: [CMS-concurrent-sweep: 0.245/0.245 secs] [Times: user=0.30 sys=0.00, real=0.24 secs]
15578645.829: [CMS-concurrent-reset-start]
15578645.855: [CMS-concurrent-reset: 0.026/0.026 secs] [Times: user=0.05 sys=0.01, real=0.03 secs] 

15578647.856: [GC [1 CMS-initial-mark: 12075999K(12582912K)] 20737398K(29360128K), 1.0872730 secs] [Times: user=1.09 sys=0.00, real=1.08 secs]
15578648.943: [CMS-concurrent-mark-start]
15578649.472: [CMS-concurrent-mark: 0.528/0.528 secs] [Times: user=2.06 sys=0.02, real=0.53 secs]
15578649.472: [CMS-concurrent-preclean-start]
15578649.507: [CMS-concurrent-preclean: 0.035/0.035 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]
15578649.507: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 15578654.961: [CMS-concurrent-abortable-preclean: 5.454/5.454 secs] [Times: user=8.15 sys=0.17, real=5.45 secs]
15578654.962: [GC[YG occupancy: 11315403 K (16777216 K)]15578654.963: [Rescan (parallel) , 1.1274320 secs]15578656.090: [weak refs processing, 0.0000240 secs]15578656.090: [scrub string table, 0.0005890 secs] [1 CMS-remark: 12075999K(12582912K)] 23391403K(29360128K), 1.1281890 secs] [Times: user=11.00 sys=0.03, real=1.13 secs]
15578656.091: [CMS-concurrent-sweep-start]
15578656.327: [CMS-concurrent-sweep: 0.236/0.236 secs] [Times: user=0.52 sys=0.01, real=0.24 secs]
15578656.327: [CMS-concurrent-reset-start]
15578656.353: [CMS-concurrent-reset: 0.026/0.026 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] </span></span>

 CMS垃圾回收的执行过程：
1、CMS-initial-mark ：初始标记，从root对象开始标记存活的对象。它花费的时间是real=1.01 secs，由于这一步骤是STW的，所以整个application被暂停了1.01秒。并且，user time和real time相差不大，所以确实是只有一个thread执行这一步；
2、CMS-concurrent-mark-start：并发标记。它执行时间是real=0.53 secs，但因为这一步是可以并发执行的，所以系统在这段时间内并没有暂停；
3、CMS-concurrent-preclean-start ：concurrent precleaning。同样的，这一步也是并发执行； 4、CMS-remark：重新标记。暂停应用程序，同时启动一定数目的垃圾回收线程，并行地标记第2阶段遗漏的对象（在并发标记阶段结束后对象状态的更新导致）。它的执行时间是real=0.97 secs。因为这是STW的步骤，并且它的pause time一般是最长的，所以这一步的执行时间会直接决定这次Full GC对系统的影响。 5、CMS-concurrent-sweep-start：并发清除。 6、CMS-concurrent-reset-start：并发重设状态等待下一次CMS的触发。 只有在第1、4阶段需要暂停所有的应用程序，其它阶段的垃圾回收线程与应用程序线程并发执行。


hadoop与hbase没有日志输出

在HADOOP_HOME/conf/env.sh里有一行设置log输出位置的，你可以修改一下，hbase同理
 

java gc的日志在什地方看？

-verbose.gc开关可显示gc的操作内容。打开它，可以显示最忙和最空闲收集行为发生的时间、收集前后的内存大小、收集需要的时间等。打开- xx:+ printgcdetails开关，可以详细了解gc中的变化。打开-XX: + PrintGCTimeStamps开关，可以了解这些垃圾收集发生的时间，自jvm启动以后以秒计量。最后，通过-xx: + PrintHeapAtGC开关了解堆的更详细的信息。为了了解新域的情况，可以通过-XX:=PrintTenuringDistribution开关了解获得使用期的对象权。
参考资料：www.javaeye.com/topic/244277
 

相关内容