powered by Jive Software

High JVM CPU and high packets/min

I’m running 3.8.2 from SVN with Hazelcast. Approx 5pm EDT the CPU on my JVM running OF went from ~2% to 50% CPU. Openfire statistics is showing I went from around 1800 packets/min to over 16,000 - Goes without saying there is also a huge amount of traffic between the two nodes over the Hazelcast ports.

If I enable debug logging, I get a whole lot of what is below - Pretty much non-stop, and it appears to be for the vast majority of clients. Debug logs rolled in about 20s, so was unable to verify all clients were included. Any suggestions? I don’t see any real impact, so I’m just letting it go for now. Maybe it will stop on it’s own, otherwise I’ll cycle it tomorrow. Is there an easy way to identify what the 16k packets/min are? I connected to it with Spark in debug mode, but I didn’t see any messages other than the usual infrequent presence changes.

2013.04.06 19:13:26 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/10

.246.13.39:1206] Filtered Write: org.apache.mina.filter.support.SSLHandler@5f34

9285

2013.04.06 19:13:26 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/10

.246.13.39:1206] encrypt: HeapBuffer[pos=0 lim=171 cap=4096: 3C 70 72 65 73 65

6E 63 65 20 69 64 3D 22 54 45 4C 75 6D 2D 31 38 34 22 20 66 72 6F 6D 3D 22 70 68

61 72 76 65 79 40 6A 65 77 65 6C 73 2E 63 6F 6D 2F 73 70 61 72 6B 22 20 74 6F 3

D 22 6C 70 73 69 68 6F 75 6E 74 61 6B 69 73 40 6A 65 77 65 6C 73 2E 63 6F 6D 22

3E 3C 73 74 61 74 75 73 3E 41 77 61 79 20 64 75 65 20 74 6F 20 69 64 6C 65 2E 3C

2F 73 74 61 74 75 73 3E 3C 70 72 69 6F 72 69 74 79 3E 30 3C 2F 70 72 69 6F 72 6

9 74 79 3E 3C 73 68 6F 77 3E 61 77 61 79 3C 2F 73 68 6F 77 3E 3C 2F 70 72 65 73

65 6E 63 65 3E]

2013.04.06 19:13:26 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/10

.246.13.39:1206] Wrap res:Status = OK HandshakeStatus = NOT_HANDSHAKING

bytesConsumed = 171 bytesProduced = 192

2013.04.06 19:13:26 org.jivesoftware.openfire.nio.ClientConnectionHandler - [/10

.246.13.39:1206] encrypted buf: HeapBuffer[pos=0 lim=192 cap=192: 17 03 01 00 B

B 2C 98 A6 DF 3B 63 13 EE C2 F6 89 FB D7 CD 9D 0A 6F EE 48 C9 AC E4 6B 99 17 D6

82 0C 51 A3 21 E4 BB F5 B7 18 AC 14 8B D6 B6 A5 E8 23 23 EB A2 92 A8 2C A4 B9 E0

41 AA 3F B2 C6 09 66 1B 0E 64 C7 98 D2 CE AF 75 56 94 1B A6 02 AC 9E 6A 9A A5 C

B D6 53 51 14 D1 4C 07 F2 00 B0 24 4B 89 81 5C B6 10 F0 DF F7 BE 1D 57 97 39 E6

BD 9F A4 FA DC 3C D6 6F 9F FC 7E 48 97 13 F9 24 E2 5D 28 9F 51 34 D1 F3 4D 98 22

AC B9 CB 7A 77 A0 F5 D4 12 8C 29 11 C7 1A A6 4C 4A 2C 74 66 68 B4 2A E6 C8 6D 3

F E1 37 32 38 A4 A2 F7 6D F6 8E 48 15 5E 57 8B 3C 6C A1 09 28 04 78 21 99 30 BE

50]

2013.04.06 19:13:26 com.jivesoftware.util.cache.ClusteredCacheFactory - Callable

Task[com.jivesoftware.util.cluster.RemotePacketExecution] result: null

2013.04.06 19:13:26 org.apache.mina.filter.executor.ExecutorFilter - Launching t

hread for /10.246.13.39:1206

2013.04.06 19:13:26 org.apache.mina.filter.executor.ExecutorFilter - Exiting sin

ce queue is empty for /10.246.13.39:1206

I stopped the JVM on node02, and the problem went away even after it restarted and rejoined the cluster.

If anyone wants the heapdumps/threaddumps I did on both nodes before I cycled 02 let me know.

After I cycled my node02, both nodes had this in warn.log - Didn’t seem to cause problems, but filled up the logs quickly.

2013.04.07 07:29:16 com.jivesoftware.util.cache.ClusteredCacheFactory - Requested node 0329c157-5747-4611-9bdf-3f12c5e61908 not found in cluster