Performance Test
Hazelcast 5.5.0
Test Class
We are using the following code to test throughput latencies of the Hazelcast service on 1 node:
import com.hazelcast.core.Hazelcast;
import com.hazelcast.core.HazelcastInstance;
import com.hazelcast.map.IMap;
import java.util.HashMap;
public class HazelcastTest {
public static void main(String[] args) throws Throwable{
HazelcastInstance hz = Hazelcast.newHazelcastInstance();
IMap map = hz.getMap("testMap");
int MAX = 200000;
long mainstart = System.nanoTime();
long bytes_sent = 0;
HashMap batch = new HashMap<>();
for(int i=0; i<MAX; i++){
String a = java.util.UUID.randomUUID().toString();
String b = java.util.UUID.randomUUID().toString();
bytes_sent+=a.getBytes().length+b.getBytes().length;
batch.put(a,b);
if (batch.size() == 1000) {
map.putAll(batch);
batch.clear();
}
}
if (!batch.isEmpty()) {
map.putAll(batch);
}
long end = System.nanoTime();
long elapsedNs = end - mainstart;
double elapsedMs = elapsedNs / 1_000_000.0;
System.out.println("* "+MAX+" items added ("+bytes_sent+" bytes sent) in "+elapsedMs+"ms");
hz.shutdown();
}
}
The command line used is (the com.hazelcast.internal.cluster package was filtered down by using a wider regex net initially):
java -javaagent:TopJ.jar=1,20,'com.hazelcast.internal.cluster',err -cp .:hazelcast-5.5.0.jar HazelcastTest
Results
[TopJ] Top 20 Method Timing Stats for 12 Threads (sorted by avg time)
[TopJ] com.hazelcast.internal.cluster.impl.ClusterDataSerializerHook.createFactory: max=2075.44 ms, total=2075.45 ms, avg=1037.73 ms, calls=2
[TopJ] com.hazelcast.internal.cluster.impl.MulticastService.receive: max=1003.61 ms, total=5430.87 ms, avg=201.14 ms, calls=27
[TopJ] com.hazelcast.internal.cluster.impl.ClusterServiceImpl.init: max=32.62 ms, total=32.62 ms, avg=32.62 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.ClusterServiceImpl.registerMetrics: max=31.19 ms, total=31.19 ms, avg=31.19 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.MulticastService.createMulticastService: max=6.91 ms, total=6.91 ms, avg=6.91 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.MembershipManager.sendMembershipEventNotifications: max=6.24 ms, total=6.24 ms, avg=6.24 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.MulticastService.stop: max=4.75 ms, total=4.75 ms, avg=4.75 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.MemberSelectingCollection.iterator: max=11.55 ms, total=11.56 ms, avg=2.89 ms, calls=4
[TopJ] com.hazelcast.internal.cluster.impl.ClusterServiceImpl.addMembershipListener: max=2.46 ms, total=2.46 ms, avg=2.46 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.MulticastService.configureMulticastSocket: max=2.08 ms, total=2.08 ms, avg=2.08 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.MembershipManager.init: max=1.03 ms, total=1.03 ms, avg=1.03 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.ClusterServiceImpl.dispatchEvent: max=0.51 ms, total=0.51 ms, avg=0.51 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.ClusterHeartbeatManager.init: max=0.43 ms, total=0.43 ms, avg=0.43 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.ClusterStateManager.doSetClusterVersion: max=0.35 ms, total=0.35 ms, avg=0.35 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.ClusterServiceImpl.setJoined: max=1.20 ms, total=1.37 ms, avg=0.34 ms, calls=4
[TopJ] com.hazelcast.internal.cluster.impl.MembershipManager.sendMembershipEvents: max=0.30 ms, total=0.30 ms, avg=0.30 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.ClusterServiceImpl.getMembers: max=63.00 ms, total=64.33 ms, avg=0.30 ms, calls=214
[TopJ] com.hazelcast.internal.cluster.impl.operations.OnJoinOp.writeInternal: max=0.46 ms, total=5.10 ms, avg=0.21 ms, calls=24
[TopJ] com.hazelcast.internal.cluster.impl.MembersView.createNew: max=0.21 ms, total=0.21 ms, avg=0.21 ms, calls=1
[TopJ] com.hazelcast.internal.cluster.impl.MemberMap.toMembersView: max=0.20 ms, total=0.20 ms, avg=0.20 ms, calls=1
Most of the slower calls are boot-time caching of classes and aren't a major issue, so were filtered out.
What seems to be an issue is the highlighted method call. Under closer inspection the code is:
private JoinMessage receive() {
try {
try {
multicastSocket.receive(datagramPacketReceive);
} catch (IOException ignore) {
return null;
}
try {
final byte[] data = datagramPacketReceive.getData();
final int offset = datagramPacketReceive.getOffset();
final int length = datagramPacketReceive.getLength();
final byte[] processed = inputProcessor != null ? inputProcessor.process(data, offset, length) : data;
final BufferObjectDataInput input = node.getSerializationService().createObjectDataInput(processed);
if (inputProcessor == null) {
// If pre-processed the offset is already taken into account.
input.position(offset);
}
final byte packetVersion = input.readByte();
if (packetVersion != Packet.VERSION) {
logger.warning("Received a JoinRequest with a different packet version, or encrypted. "
+ "Verify that the sender Node, doesn't have symmetric-encryption on. This -> "
+ Packet.VERSION + ", Incoming -> " + packetVersion
+ ", Sender -> " + datagramPacketReceive.getAddress());
return null;
}
return input.readObject();
} catch (Exception e) {
if (e instanceof EOFException || e instanceof HazelcastSerializationException) {
long now = System.currentTimeMillis();
if (now - lastLoggedJoinSerializationFailure > JOIN_SERIALIZATION_ERROR_SUPPRESSION_MILLIS) {
lastLoggedJoinSerializationFailure = now;
logger.warning("Received a JoinRequest with an incompatible binary-format. "
+ "An old version of Hazelcast may be using the same multicast discovery port. "
+ "Are you running multiple Hazelcast clusters on this host? "
+ "(This message will be suppressed for 60 seconds). ");
}
} else if (e instanceof GeneralSecurityException) {
logger.warning("Received a JoinRequest with an incompatible encoding. "
+ "Symmetric-encryption is enabled on this node, the remote node either doesn't have it on, "
+ "or it uses different cipher."
+ "(This message will be suppressed for 60 seconds). ");
} else {
throw e;
}
}
} catch (Exception e) {
logger.warning(e);
}
return null;
}
We are blocking on a multicast socket. Multicast sockets are good for small data ping packets but not when there are heavier payloads which this test demonstrates. The bandwidth is being constrained
by the underlying network and has overheads that can be avoided by not using it as a main data channel.
Solution
The solution to increase throughput would be do change to unicast or TCP for the data sending and using multicast for the subscribing (ie. keep alive pings).
This would increase bandwidth significantly. The test results:
Uninstrumented HazelCastTest: 200000 items added (14400000 bytes sent) in 2118.256491ms
Modified approach UnicastClusterDemo: 1400 bytes from /lanip:42738, total recv: 15015000 bytes in 368ms
The speed increase is 5.76
