Again : java process 100percent and memory garbage collection

[dimbraaa]

Hello,

A java process consumes more and more cpu time after time, until load average grows > 100%; So i reboot the server (services restart would be enough), and CPU usage goes well again for some time.

There's a kind of similar problem here : java process loads the CPU to more than 100 percent, but i've some others pieces of information.

I've ZCS 8.0.9, ZxSuite 1.10.2 with only ZxChat enabled at the moment.
Server is a vm with 2vCPU, 10g RAM for ~200 mailboxes.

When issue occurs, i see a lot of memory garbage collection in zmmmailboxd.out ; i don't have that behavior for some time after server reboots (= GC are less frequents)

I opened a case to Zimbra support and gave them a zmdiaglog

They found no issue related to Zimbra service, but found some third-party application thead (= Zextras) possible issue. Relevant log they gave me :

"ZeXtras Activity Thread" daemon prio=10 tid=0x00007f2e59a60000 nid=0xfa4 waiting on condition [0x00007f2e0f8a1000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000078f817cf8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
at com.zextras.lib.activities.ActivityThread.run(ActivityThread.java:105)
Locked ownable synchronizers:
- None

My Java configuration from zmlocalconfig :

mailboxd_java_heap_new_size_percent = 25
mailboxd_java_heap_size = 1979
mailboxd_java_options = -server -Djava.awt.headless=true -Dsun.net.inetaddr.ttl=60 -XX:+UseConcMarkSweepGC -XXermSize=196m -XX:MaxPermSize=350m -XX:SoftRefLRUPolicyMSPerMB=1 -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationstoppedTime -XXmitStackTraceInFastThrow -Djava.net.preferIPv4Stack=true -Dorg.apache.jasper.compiler.disablejsr199=true
[...]
zimbra_zmjava_options = -Xmx256m -Djava.net.preferIPv4Stack=true

zmmmailboxd.out with those too-frequent memory garbage collections :

3565723.100: [GC3565723.100: [ParNew: 417180K->11951K(455296K), 0.0273460 secs] 1592860K->1190368K(1976960K), 0.0274620 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
3565723.128: Total time for which application threads were stopped: 0.0286110 seconds
3565725.716: [GC3565725.716: [ParNew: 416687K->9876K(455296K), 0.0222920 secs] 1595104K->1191999K(1976960K), 0.0224000 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
3565725.738: Total time for which application threads were stopped: 0.0237430 seconds
3565727.185: Total time for which application threads were stopped: 0.0011250 seconds
3565727.392: Total time for which application threads were stopped: 0.0008220 seconds
3565728.011: [GC3565728.011: [ParNew: 414612K->8522K(455296K), 0.0203050 secs] 1596735K->1191315K(1976960K), 0.0204110 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
3565728.032: Total time for which application threads were stopped: 0.0215630 seconds
3565728.038: Total time for which application threads were stopped: 0.0007430 seconds
3565730.415: [GC3565730.415: [ParNew: 413258K->11715K(455296K), 0.0195100 secs] 1596051K->1195566K(1976960K), 0.0196390 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]
3565730.434: Total time for which application threads were stopped: 0.0209150 seconds
3565733.308: [GC3565733.308: [ParNew: 416451K->10624K(455296K), 0.0397030 secs] 1600302K->1195931K(1976960K), 0.0398110 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]
3565733.348: Total time for which application threads were stopped: 0.0409560 seconds
3565734.779: Total time for which application threads were stopped: 0.0093450 seconds
3565734.924: Total time for which application threads were stopped: 0.0050160 seconds
3565734.929: Total time for which application threads were stopped: 0.0003740 seconds
3565736.710: [GC3565736.710: [ParNew: 415360K->8221K(455296K), 0.0636480 secs] 1600667K->1193819K(1976960K), 0.0637530 secs] [Times: user=0.04 sys=0.00, real=0.06 secs]

Thanks for your help !

[Cine]

Hello dimbraaa,
welcome to the forums!

The

"ZeXtras Activity Thread" daemon prio=10 tid=0x00007f2e59a60000 nid=0xfa4 waiting on condition [0x00007f2e0f8a1000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000078f817cf8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
at com.zextras.lib.activities.ActivityThread.run(ActivityThread.java:105)
Locked ownable synchronizers:
- None

log extract means that a ZeXtras Suite thread is on WAITING state - which is perfectly normal and doesn't cause the CPU load to go up by itself - and the GC data doesn't seem off the charts...

Could you please run the following commands as soon as the CPU spikes up again and email me the output files (community@zextras.com)?

 for i in {1..30}; do /opt/zimbra/bin/zmthrdump > /tmp/thrdump.$i.log ; sleep 1 ; done

/opt/zimbra/libexec/zmdiaglog -a -j -z -d /tmp/zmdiaglog_full

(run the first as the 'zimbra' user and the second one as root)

Have a nice day,
Cine
the ZeXtras Team

[joviermark]

More on...Memory Management in Java

Mark