Home | About | Sematext search-lucene.com search-hadoop.com
 Search Hadoop and all its subprojects:

Switch to Threaded View
HBase, mail # user - GC and High CPU


Copy link to this message
-
Re: GC and High CPU
Jack Levin 2011-05-16, 23:11
I think this will resolve my issue, here is the output:

     14 2011-05-16T15:58
     13 2011-05-16T15:59
     12 2011-05-16T16:00
     14 2011-05-16T16:01
     14 2011-05-16T16:02
     13 2011-05-16T16:03
     11 2011-05-16T16:04
     12 2011-05-16T16:05
     11 2011-05-16T16:06
16:06:55 10.103.7.27 root@mtag27:/usr/lib/hbase/logs $ tail -f gc-hbase.log
2011-05-16T16:06:05.528-0700: 1725.183: [GC 1725.183: [ParNew:
76665K->7644K(76672K), 0.0301560 secs] 3255607K->3194064K(12279488K)
icms_dc=0 , 0.0302940 secs] [Times: user=0.09 sys=0.01, real=0.03
secs]
2011-05-16T16:06:11.457-0700: 1731.112: [GC 1731.112: [ParNew:
75800K->7168K(76672K), 0.0311670 secs] 3262220K->3198429K(12279488K)
icms_dc=0 , 0.0312880 secs] [Times: user=0.09 sys=0.00, real=0.03
secs]
2011-05-16T16:06:16.546-0700: 1736.202: [GC 1736.202: [ParNew:
75328K->7674K(76672K), 0.0270760 secs] 3266589K->3203675K(12279488K)
icms_dc=0 , 0.0271940 secs] [Times: user=0.09 sys=0.01, real=0.03
secs]
2011-05-16T16:06:21.407-0700: 1741.063: [GC 1741.063: [ParNew:
75832K->8512K(76672K), 0.0285340 secs] 3271833K->3209994K(12279488K)
icms_dc=0 , 0.0286380 secs] [Times: user=0.07 sys=0.01, real=0.03
secs]
2011-05-16T16:06:26.571-0700: 1746.226: [GC 1746.226: [ParNew:
76627K->6049K(76672K), 0.0254590 secs] 3278109K->3213405K(12279488K)
icms_dc=0 , 0.0255890 secs] [Times: user=0.08 sys=0.00, real=0.03
secs]
Now running GC less often with larger cleans. And here is another
server that runs under same load:

     40 2011-05-16T15:53
     50 2011-05-16T15:54
     45 2011-05-16T15:55
     43 2011-05-16T15:56
     39 2011-05-16T15:57
     37 2011-05-16T15:58
     37 2011-05-16T15:59
     35 2011-05-16T16:00
     36 2011-05-16T16:01
     25 2011-05-16T16:02
16:08:39 10.103.7.25 root@mtag25:/usr/lib/hbase/logs $ tail -f gc-hbase.log
2011-05-16T16:08:29.154-0700: 171956.381: [GC 171956.382: [ParNew:
19130K->2112K(19136K), 0.0403890 secs] 6649843K->6634911K(11885508K),
0.0407000 secs] [Times: user=0.15 sys=0.01, real=0.04 secs]
2011-05-16T16:08:30.237-0700: 171957.464: [GC 171957.465: [ParNew:
19077K->2112K(19136K), 0.0367750 secs] 6651877K->6636722K(11885508K),
0.0369370 secs] [Times: user=0.14 sys=0.00, real=0.04 secs]
2011-05-16T16:08:31.864-0700: 171959.092: [GC 171959.092: [ParNew:
19120K->1656K(19136K), 0.0396040 secs] 6653731K->6637891K(11885508K),
0.0397500 secs] [Times: user=0.14 sys=0.01, real=0.04 secs]
2011-05-16T16:08:33.551-0700: 171960.778: [GC 171960.779: [ParNew:
18620K->2112K(19136K), 0.0398640 secs] 6654855K->6638900K(11885508K),
0.0400910 secs] [Times: user=0.15 sys=0.00, real=0.04 secs]
2011-05-16T16:08:35.116-0700: 171962.344: [GC 171962.344: [ParNew:
19136K->2112K(19136K), 0.0375530 secs] 6655924K->6641070K(11885508K),
0.0377090 secs] [Times: user=0.14 sys=0.01, real=0.04 secs]
2011-05-16T16:08:36.562-0700: 171963.790: [GC 171963.790: [ParNew:
19131K->1763K(19136K), 0.0453660 secs] 6658090K->6642325K(11885508K),
0.0455130 secs] [Times: user=0.17 sys=0.00, real=0.04 secs]
2011-05-16T16:08:37.675-0700: 171964.903: [GC 171964.903: [ParNew:
18733K->1400K(19136K), 0.0457320 secs] 6659295K->6643257K(11885508K),
0.0459240 secs] [Times: user=0.17 sys=0.00, real=0.05 secs]
Way more often, less to clean, and CPU usage is visibly higher.  And
GC config changes are:
export HBASE_OPTS="$HBASE_OPTS -XX:+UseConcMarkSweepGC
-XX:MaxDirectMemorySize=2G"

# Uncomment below to enable java garbage collection logging.
export HBASE_OPTS="$HBASE_OPTS -verbose:gc -Xms12000m
-XX:CMSInitiatingOccupancyFraction=70 -XX:+PrintGCDetails
-XX:+PrintGCDateStamps -XX:+HeapDumpOnOutOfMemoryError
-Xloggc:$HBASE_HOME/logs/gc-hbase.log \
-XX:+CMSIncrementalMode \  <--------
-XX:+CMSIncrementalPacing \ <-------
-XX:-TraceClassUnloading <---------------

This way GC statistically adapts, and lesses the load on CPU.

-Jack
On Mon, May 16, 2011 at 3:17 PM, Jack Levin <[EMAIL PROTECTED]> wrote:
> hlog rolled, and qps was at 1000, not much at all.  I tend to believe
> that concurrent GC collection is taking way too many threads from the