You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@kafka.apache.org by jinhong lu <lu...@gmail.com> on 2016/04/11 12:08:14 UTC
Minor GC time becomes longer and longer
Minor GC time in my cluster becomes longer and longer, and broker loss session with zk:
2016-04-11T17:33:06.559+0800: 875.917: [GC2016-04-11T17:33:06.559+0800: 875.917: [ParNew: 3363139K->10287K(3774912K), 0.0858010 secs] 3875141K->522289K(31037888K), 0.0860890 secs] [Times: user=1.46 sys=0.02, real=0.09 secs]
2016-04-11T17:38:50.477+0800: 1219.834: [GC2016-04-11T17:38:50.477+0800: 1219.835: [ParNew: 3365807K->11295K(3774912K), 0.0858600 secs] 3877809K->523297K(31037888K), 0.0861390 secs] [Times: user=1.50 sys=0.00, real=0.08 secs]
2016-04-11T17:46:58.550+0800: 1707.908: [GC2016-04-11T17:46:58.550+0800: 1707.908: [ParNew: 3366815K->8463K(3774912K), 15.8853640 secs] 3878817K->526017K(31037888K), 15.8855810 secs] [Times: user=286.22 sys=0.00, real=15.89 secs]
2016-04-11T17:54:37.601+0800: 2166.959: [GC2016-04-11T17:54:37.601+0800: 2166.959: [ParNew: 3363983K->5961K(3774912K), 22.5800540 secs] 3881537K->523515K(31037888K), 22.5803030 secs] [Times: user=406.07 sys=0.00, real=22.58 secs]
Here is my jvm setting:
28808 kafka.Kafka -Xmx30G -Xms30G -Xmn4G -XX:+UseCompressedOops -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0 -XX:+CMSParallelRemarkEnabled -XX:+DisableExplicitGC -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=75 -Xnoclassgc -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+CMSScavengeBeforeRemark -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/home/hadoop/kafka/bin/../logs/kafkaServer-gc.log -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dkafka.logs.dir=/home/hadoop/kafka/bin/../logs -Dlog4j.configuration=file:bin/../config/log4j.properties
Any suggestion to tune the jvm ?
Thanks,
lujinhong
Re: Minor GC time becomes longer and longer
Posted by Alexis Midon <al...@airbnb.com.INVALID>.
Any experience with G1 for Kafka? I didn't get a chance to try it out.
On Mon, Apr 11, 2016 at 3:31 AM Jakub Neubauer <ja...@gmail.com>
wrote:
> Hi,
> Did you consider G1 collector?
> http://docs.oracle.com/javase/7/docs/technotes/guides/vm/G1.html
> Jakub N.
>
> On 11.4.2016 12:08, jinhong lu wrote:
> > Minor GC time in my cluster becomes longer and longer, and broker loss
> session with zk:
> >
> > 2016-04-11T17:33:06.559+0800: 875.917:
> [GC2016-04-11T17:33:06.559+0800: 875.917: [ParNew:
> 3363139K->10287K(3774912K), 0.0858010 secs] 3875141K->522289K(31037888K),
> 0.0860890 secs] [Times: user=1.46 sys=0.02, real=0.09 secs]
> > 2016-04-11T17:38:50.477+0800: 1219.834:
> [GC2016-04-11T17:38:50.477+0800: 1219.835: [ParNew:
> 3365807K->11295K(3774912K), 0.0858600 secs] 3877809K->523297K(31037888K),
> 0.0861390 secs] [Times: user=1.50 sys=0.00, real=0.08 secs]
> > 2016-04-11T17:46:58.550+0800: 1707.908:
> [GC2016-04-11T17:46:58.550+0800: 1707.908: [ParNew:
> 3366815K->8463K(3774912K), 15.8853640 secs] 3878817K->526017K(31037888K),
> 15.8855810 secs] [Times: user=286.22 sys=0.00, real=15.89 secs]
> > 2016-04-11T17:54:37.601+0800: 2166.959:
> [GC2016-04-11T17:54:37.601+0800: 2166.959: [ParNew:
> 3363983K->5961K(3774912K), 22.5800540 secs] 3881537K->523515K(31037888K),
> 22.5803030 secs] [Times: user=406.07 sys=0.00, real=22.58 secs]
> >
> > Here is my jvm setting:
> >
> > 28808 kafka.Kafka -Xmx30G -Xms30G -Xmn4G -XX:+UseCompressedOops
> -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled
> -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0
> -XX:+CMSParallelRemarkEnabled -XX:+DisableExplicitGC
> -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=75
> -Xnoclassgc -XX:+UseParNewGC -XX:+UseConcMarkSweepGC
> -XX:+CMSClassUnloadingEnabled -XX:+CMSScavengeBeforeRemark
> -XX:+DisableExplicitGC -Djava.awt.headless=true
> -Xloggc:/home/hadoop/kafka/bin/../logs/kafkaServer-gc.log -verbose:gc
> -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps
> -Dcom.sun.management.jmxremote
> -Dcom.sun.management.jmxremote.authenticate=false
> -Dcom.sun.management.jmxremote.ssl=false
> -Dkafka.logs.dir=/home/hadoop/kafka/bin/../logs
> -Dlog4j.configuration=file:bin/../config/log4j.properties
> >
> > Any suggestion to tune the jvm ?
> >
> >
> > Thanks,
> > lujinhong
> >
>
>
Re: Minor GC time becomes longer and longer
Posted by Jakub Neubauer <ja...@gmail.com>.
Hi,
Did you consider G1 collector?
http://docs.oracle.com/javase/7/docs/technotes/guides/vm/G1.html
Jakub N.
On 11.4.2016 12:08, jinhong lu wrote:
> Minor GC time in my cluster becomes longer and longer, and broker loss session with zk:
>
> 2016-04-11T17:33:06.559+0800: 875.917: [GC2016-04-11T17:33:06.559+0800: 875.917: [ParNew: 3363139K->10287K(3774912K), 0.0858010 secs] 3875141K->522289K(31037888K), 0.0860890 secs] [Times: user=1.46 sys=0.02, real=0.09 secs]
> 2016-04-11T17:38:50.477+0800: 1219.834: [GC2016-04-11T17:38:50.477+0800: 1219.835: [ParNew: 3365807K->11295K(3774912K), 0.0858600 secs] 3877809K->523297K(31037888K), 0.0861390 secs] [Times: user=1.50 sys=0.00, real=0.08 secs]
> 2016-04-11T17:46:58.550+0800: 1707.908: [GC2016-04-11T17:46:58.550+0800: 1707.908: [ParNew: 3366815K->8463K(3774912K), 15.8853640 secs] 3878817K->526017K(31037888K), 15.8855810 secs] [Times: user=286.22 sys=0.00, real=15.89 secs]
> 2016-04-11T17:54:37.601+0800: 2166.959: [GC2016-04-11T17:54:37.601+0800: 2166.959: [ParNew: 3363983K->5961K(3774912K), 22.5800540 secs] 3881537K->523515K(31037888K), 22.5803030 secs] [Times: user=406.07 sys=0.00, real=22.58 secs]
>
> Here is my jvm setting:
>
> 28808 kafka.Kafka -Xmx30G -Xms30G -Xmn4G -XX:+UseCompressedOops -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0 -XX:+CMSParallelRemarkEnabled -XX:+DisableExplicitGC -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=75 -Xnoclassgc -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+CMSScavengeBeforeRemark -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/home/hadoop/kafka/bin/../logs/kafkaServer-gc.log -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dkafka.logs.dir=/home/hadoop/kafka/bin/../logs -Dlog4j.configuration=file:bin/../config/log4j.properties
>
> Any suggestion to tune the jvm ?
>
>
> Thanks,
> lujinhong
>
Re: Minor GC time becomes longer and longer
Posted by Alexis Midon <al...@airbnb.com.INVALID>.
Why such a gigantic heap? 30G.
In my experience, Kafka broker does not have to deal with long-lived
objects, it's all about many small, ephemeral objects. Most of the data is
kept off heap.
We've been happy with 5G heap, 2G being for the new generation. The server
has 8 cores and 60GB of ram.
Here are the jvm settings:
```
-XX:+AggressiveOpts -XX:+UseCompressedOops -XX:+UseFastEmptyMethods
-XX:+UseFastAccessorMethods -XX:+CMSClassUnloadingEnabled -Xms5g -Xmx5g
-XX:NewSize=2g -XX:MaxNewSize=2g -XX:+UseParNewGC -XX:ParallelGCThreads=8
-XX:MaxTenuringThreshold=15 -XX:SurvivorRatio=30 -XX:+UseConcMarkSweepGC
-XX:+CMSConcurrentMTEnabled
```
The GC logs look ok.
http://pastebin.com/rDyGNttY
Of course, let's not forget that GC tuning is tricky and can't be solved
over an email.
On Mon, Apr 11, 2016 at 3:31 AM Jakub Neubauer <ja...@gmail.com>
wrote:
> Hi,
> Did you consider G1 collector?
> http://docs.oracle.com/javase/7/docs/technotes/guides/vm/G1.html
> Jakub N.
>
> On 11.4.2016 12:08, jinhong lu wrote:
> > Minor GC time in my cluster becomes longer and longer, and broker loss
> session with zk:
> >
> > 2016-04-11T17:33:06.559+0800: 875.917:
> [GC2016-04-11T17:33:06.559+0800: 875.917: [ParNew:
> 3363139K->10287K(3774912K), 0.0858010 secs] 3875141K->522289K(31037888K),
> 0.0860890 secs] [Times: user=1.46 sys=0.02, real=0.09 secs]
> > 2016-04-11T17:38:50.477+0800: 1219.834:
> [GC2016-04-11T17:38:50.477+0800: 1219.835: [ParNew:
> 3365807K->11295K(3774912K), 0.0858600 secs] 3877809K->523297K(31037888K),
> 0.0861390 secs] [Times: user=1.50 sys=0.00, real=0.08 secs]
> > 2016-04-11T17:46:58.550+0800: 1707.908:
> [GC2016-04-11T17:46:58.550+0800: 1707.908: [ParNew:
> 3366815K->8463K(3774912K), 15.8853640 secs] 3878817K->526017K(31037888K),
> 15.8855810 secs] [Times: user=286.22 sys=0.00, real=15.89 secs]
> > 2016-04-11T17:54:37.601+0800: 2166.959:
> [GC2016-04-11T17:54:37.601+0800: 2166.959: [ParNew:
> 3363983K->5961K(3774912K), 22.5800540 secs] 3881537K->523515K(31037888K),
> 22.5803030 secs] [Times: user=406.07 sys=0.00, real=22.58 secs]
> >
> > Here is my jvm setting:
> >
> > 28808 kafka.Kafka -Xmx30G -Xms30G -Xmn4G -XX:+UseCompressedOops
> -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled
> -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0
> -XX:+CMSParallelRemarkEnabled -XX:+DisableExplicitGC
> -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=75
> -Xnoclassgc -XX:+UseParNewGC -XX:+UseConcMarkSweepGC
> -XX:+CMSClassUnloadingEnabled -XX:+CMSScavengeBeforeRemark
> -XX:+DisableExplicitGC -Djava.awt.headless=true
> -Xloggc:/home/hadoop/kafka/bin/../logs/kafkaServer-gc.log -verbose:gc
> -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps
> -Dcom.sun.management.jmxremote
> -Dcom.sun.management.jmxremote.authenticate=false
> -Dcom.sun.management.jmxremote.ssl=false
> -Dkafka.logs.dir=/home/hadoop/kafka/bin/../logs
> -Dlog4j.configuration=file:bin/../config/log4j.properties
> >
> > Any suggestion to tune the jvm ?
> >
> >
> > Thanks,
> > lujinhong
> >
>
>
Re: Minor GC time becomes longer and longer
Posted by Jakub Neubauer <ja...@gmail.com>.
Hi,
Did you consider G1 collector?
http://docs.oracle.com/javase/7/docs/technotes/guides/vm/G1.html
Jakub N.
On 11.4.2016 12:08, jinhong lu wrote:
> Minor GC time in my cluster becomes longer and longer, and broker loss session with zk:
>
> 2016-04-11T17:33:06.559+0800: 875.917: [GC2016-04-11T17:33:06.559+0800: 875.917: [ParNew: 3363139K->10287K(3774912K), 0.0858010 secs] 3875141K->522289K(31037888K), 0.0860890 secs] [Times: user=1.46 sys=0.02, real=0.09 secs]
> 2016-04-11T17:38:50.477+0800: 1219.834: [GC2016-04-11T17:38:50.477+0800: 1219.835: [ParNew: 3365807K->11295K(3774912K), 0.0858600 secs] 3877809K->523297K(31037888K), 0.0861390 secs] [Times: user=1.50 sys=0.00, real=0.08 secs]
> 2016-04-11T17:46:58.550+0800: 1707.908: [GC2016-04-11T17:46:58.550+0800: 1707.908: [ParNew: 3366815K->8463K(3774912K), 15.8853640 secs] 3878817K->526017K(31037888K), 15.8855810 secs] [Times: user=286.22 sys=0.00, real=15.89 secs]
> 2016-04-11T17:54:37.601+0800: 2166.959: [GC2016-04-11T17:54:37.601+0800: 2166.959: [ParNew: 3363983K->5961K(3774912K), 22.5800540 secs] 3881537K->523515K(31037888K), 22.5803030 secs] [Times: user=406.07 sys=0.00, real=22.58 secs]
>
> Here is my jvm setting:
>
> 28808 kafka.Kafka -Xmx30G -Xms30G -Xmn4G -XX:+UseCompressedOops -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0 -XX:+CMSParallelRemarkEnabled -XX:+DisableExplicitGC -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=75 -Xnoclassgc -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+CMSScavengeBeforeRemark -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/home/hadoop/kafka/bin/../logs/kafkaServer-gc.log -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dkafka.logs.dir=/home/hadoop/kafka/bin/../logs -Dlog4j.configuration=file:bin/../config/log4j.properties
>
> Any suggestion to tune the jvm ?
>
>
> Thanks,
> lujinhong
>