Hbase GC log

Hbase uses zookeeper to perceive cluster members and their memory activity. If a server is suspended for a long time, it will not be able to send heartbeat information to zookeeper quorum. Other servers will think that the server has died. This causes the master to start the recovery process for it. When the server is disconnected, it will find that all its leases have expired (each time the hbase client interacts with the regionserver, a lease (lease) will be generated on the server ), the validity period of the lease is determined by the hbase parameter. regionserver. lease. period OK), and then stop. The hbase Development Team affectionately called this scenario Juliet pause.

Using the default GC in hbase, You can see long pauses in all threads, including Juliet pause, also known as "GC of Death ". You can enable GC logs in the Java Virtual Machine to help debug this problem.

Inhbase-env.sh, Cancel any of the following annotations to enable GC log:

# 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.       

Click "Local logs" to view the gc-xxx.log log in the following format:

<span style="font-size:14px;"><span style="font-family:Microsoft YaHei;font-size:12px;">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>

The execution process of CMS garbage collection:
1. CMS-Initial-MARK: initial tag. It indicates the surviving object starting from the root object. The time it takes is real = 1.01 secs. Because this step is STW, the entire application is suspended for 1.01 seconds. In addition, the difference between user time and real time is not big, so there is indeed only one thread to execute this step;
2. CMS-Concurrent-mark-start: Concurrent mark. The execution time is real = 0.53 secs, but because this step can be executed concurrently, the system has not paused during this time;
3. CMS-Concurrent-preclean-start: Concurrent precleaning. Similarly, this step is also executed concurrently; 4. CMS-remark: Re-mark. Pause the application, start a certain number of garbage collection threads, and mark objects missed in Stage 1 in parallel (as a result of updating the object status after the end of the concurrent marking stage ). The execution time is real = 0.97 secs. Because this is the STW step, and its pause time is generally the longest, the execution time of this step will directly determine the impact of this full GC on the system. 5. CMS-Concurrent-sweep-start: Concurrent cleanup. 6. CMS-Concurrent-reset-start: the concurrent resetting status is waiting for the next CMS to trigger. Only all applications need to be suspended in stages 1st and 4. The garbage collection thread and Application Thread of other stages are concurrently executed.

Hbase GC log