Use sensible heap size for Java processes in Vagrant

[slaunay]

When I am running the tests, I sometimes get out of memory errors from the Java processes running in the Vagrant VM:

vagrant@vagrant-ubuntu-trusty-64:~$ sudo tail -n 10 /var/log/upstart/kafka-909{2,5}.log 
==> /var/log/upstart/kafka-9092.log <==
[2016-10-25 21:14:16,050] INFO Client session timed out, have not heard from server in 2989ms for sessionid 0x257fdae91d40000, closing socket connection and attempting reconnect (org.apache.zookeeper.ClientCnxn)
[2016-10-25 21:14:18,800] INFO zookeeper state changed (Disconnected) (org.I0Itec.zkclient.ZkClient)
[2016-10-25 21:14:23,999] INFO Opening socket connection to server localhost/127.0.0.1:2182. Will not attempt to authenticate using SASL (unknown error) (org.apache.zookeeper.ClientCnxn)
[2016-10-25 21:14:24,220] INFO Socket connection established to localhost/127.0.0.1:2182, initiating session (org.apache.zookeeper.ClientCnxn)
OpenJDK 64-Bit Server VM warning: INFO: os::commit_memory(0x00000000f7100000, 1048576, 0) failed; error='Cannot allocate memory' (errno=12)
#
# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (malloc) failed to allocate 1048576 bytes for committing reserved memory.
# An error report file with more information is saved as:
# //hs_err_pid6243.log

==> /var/log/upstart/kafka-9095.log <==
[2016-10-25 21:13:34,637] INFO [Group Metadata Manager on Broker 9095]: Finished loading offsets from [__consumer_offsets,42] in 60 milliseconds. (kafka.coordinator.GroupMetadataManager)
[2016-10-25 21:13:34,638] INFO [Group Metadata Manager on Broker 9095]: Loading offsets and group metadata from [__consumer_offsets,7] (kafka.coordinator.GroupMetadataManager)
[2016-10-25 21:13:34,640] INFO [Group Metadata Manager on Broker 9095]: Finished loading offsets from [__consumer_offsets,7] in 2 milliseconds. (kafka.coordinator.GroupMetadataManager)
[2016-10-25 21:13:34,668] INFO [Group Metadata Manager on Broker 9095]: Loading offsets and group metadata from [__consumer_offsets,32] (kafka.coordinator.GroupMetadataManager)
[2016-10-25 21:13:34,704] INFO [Group Metadata Manager on Broker 9095]: Finished loading offsets from [__consumer_offsets,32] in 19 milliseconds. (kafka.coordinator.GroupMetadataManager)
#
# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (malloc) failed to allocate 32744 bytes for ChunkPool::allocate
# An error report file with more information is saved as:
# //hs_err_pid6310.log

This is actually fairly easy to reproduce when running the tests and benchmarks multiple times:

$ vagrant up
$ export KAFKA_VERSION=0.9.0.1
$ go test
$ ...
$ go test -v -bench=. -run=^$
BenchmarkProducerSmall-8                       50000         42853 ns/op
BenchmarkProducerMedium-8                          3     429515749 ns/op
BenchmarkProducerLarge-8                    --- FAIL: BenchmarkProducerLarge-8
    client_test.go:13: kafka: Failed to deliver 5 messages.
--- FAIL: BenchmarkProducerSmallSinglePartition
    client_test.go:13: kafka: Failed to deliver 1 messages.
--- FAIL: BenchmarkProducerMediumSnappy
    client_test.go:13: kafka: Failed to deliver 1 messages.
FAIL
exit status 1
FAIL    github.com/Shopify/sarama   10.979s

The reason is that the Vagrant VM is provided with 3GB of RAM but the Java processes consumes up to 5*(1GB + 512MB) = 7.5 GB when not tuned:

$ ps -ef | grep java
root      6207     1  0 18:28 ?        00:00:01 java -Xmx512M -Xms512M -server -XX:+UseG1GC -XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=35 -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/opt/kafka-9091/bin/../logs/zookeeper-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=/opt/kafka-9091/bin/../logs -Dlog4j.configuration=file:/opt/kafka-9091/bin/../config/log4j.properties -cp :/opt/kafka-9091/bin/../libs/* org.apache.zookeeper.server.quorum.QuorumPeerMain /opt/kafka-9091/config/zookeeper.properties
root      6228     1  0 18:28 ?        00:00:02 java -Xmx512M -Xms512M -server -XX:+UseG1GC -XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=35 -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/opt/kafka-9092/bin/../logs/zookeeper-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=/opt/kafka-9092/bin/../logs -Dlog4j.configuration=file:/opt/kafka-9092/bin/../config/log4j.properties -cp :/opt/kafka-9092/bin/../libs/* org.apache.zookeeper.server.quorum.QuorumPeerMain /opt/kafka-9092/config/zookeeper.properties
root      6249     1  0 18:28 ?        00:00:01 java -Xmx512M -Xms512M -server -XX:+UseG1GC -XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=35 -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/opt/kafka-9093/bin/../logs/zookeeper-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=/opt/kafka-9093/bin/../logs -Dlog4j.configuration=file:/opt/kafka-9093/bin/../config/log4j.properties -cp :/opt/kafka-9093/bin/../libs/* org.apache.zookeeper.server.quorum.QuorumPeerMain /opt/kafka-9093/config/zookeeper.properties
root      6274     1  0 18:28 ?        00:00:01 java -Xmx512M -Xms512M -server -XX:+UseG1GC -XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=35 -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/opt/kafka-9094/bin/../logs/zookeeper-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=/opt/kafka-9094/bin/../logs -Dlog4j.configuration=file:/opt/kafka-9094/bin/../config/log4j.properties -cp :/opt/kafka-9094/bin/../libs/* org.apache.zookeeper.server.quorum.QuorumPeerMain /opt/kafka-9094/config/zookeeper.properties
root      6298     1  0 18:28 ?        00:00:02 java -Xmx512M -Xms512M -server -XX:+UseG1GC -XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=35 -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/opt/kafka-9095/bin/../logs/zookeeper-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=/opt/kafka-9095/bin/../logs -Dlog4j.configuration=file:/opt/kafka-9095/bin/../config/log4j.properties -cp :/opt/kafka-9095/bin/../libs/* org.apache.zookeeper.server.quorum.QuorumPeerMain /opt/kafka-9095/config/zookeeper.properties
root      6361     1  4 18:28 ?        00:00:17 java -Xmx1G -Xms1G -server -XX:+UseG1GC -XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=35 -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/opt/kafka-9091/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=/opt/kafka-9091/bin/../logs -Dlog4j.configuration=file:/opt/kafka-9091/bin/../config/log4j.properties -cp :/opt/kafka-9091/bin/../libs/* kafka.Kafka /opt/kafka-9091/config/server.properties
root      6369     1  4 18:28 ?        00:00:18 java -Xmx1G -Xms1G -server -XX:+UseG1GC -XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=35 -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/opt/kafka-9092/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=/opt/kafka-9092/bin/../logs -Dlog4j.configuration=file:/opt/kafka-9092/bin/../config/log4j.properties -cp :/opt/kafka-9092/bin/../libs/* kafka.Kafka /opt/kafka-9092/config/server.properties
root      6385     1  4 18:28 ?        00:00:17 java -Xmx1G -Xms1G -server -XX:+UseG1GC -XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=35 -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/opt/kafka-9093/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=/opt/kafka-9093/bin/../logs -Dlog4j.configuration=file:/opt/kafka-9093/bin/../config/log4j.properties -cp :/opt/kafka-9093/bin/../libs/* kafka.Kafka /opt/kafka-9093/config/server.properties
root      6393     1  4 18:28 ?        00:00:18 java -Xmx1G -Xms1G -server -XX:+UseG1GC -XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=35 -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/opt/kafka-9094/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=/opt/kafka-9094/bin/../logs -Dlog4j.configuration=file:/opt/kafka-9094/bin/../config/log4j.properties -cp :/opt/kafka-9094/bin/../libs/* kafka.Kafka /opt/kafka-9094/config/server.properties
root      6409     1  4 18:28 ?        00:00:18 java -Xmx1G -Xms1G -server -XX:+UseG1GC -XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=35 -XX:+DisableExplicitGC -Djava.awt.headless=true -Xloggc:/opt/kafka-9095/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=/opt/kafka-9095/bin/../logs -Dlog4j.configuration=file:/opt/kafka-9095/bin/../config/log4j.properties -cp :/opt/kafka-9095/bin/../libs/* kafka.Kafka /opt/kafka-9095/config/server.properties

Using smaller heap sizes fixes the issue.

Code change:

• use -Xmx320M for Kafka processes instead of -Xmx1G -Xms1G
• use -Xmx192M for Kafka processes instead of -Xmx512M -Xms512M

[eapache]

Nice, thanks!