High GC object churn with many threads in org.apache.cxf.endpoint.ClientImpl

Environment

• JBoss Enterprise Application Platform (EAP) 6.x

Issue

• JBoss is performing poorly and GC occurs very frequently. It frees plenty of space, but the old generation fills rapidly again to cause Full GCs again. Thread dumps during this time show many threads in org.apache.cxf.endpoint.ClientImpl, appending strings and copying arrays:

"JSFqueue-threads - 239" prio=10 tid=0x00007f4608524000 nid=0x5cca runnable [0x00007f45b3fb6000]
   java.lang.Thread.State: RUNNABLE
	at java.util.Arrays.copyOf(Arrays.java:2882)
	at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:100)
	at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:390)
	at java.lang.StringBuilder.append(StringBuilder.java:119)
	at java.util.Arrays.toString(Arrays.java:4071)
	at java.util.concurrent.CopyOnWriteArrayList.toString(CopyOnWriteArrayList.java:860)
	at java.lang.String.valueOf(String.java:2826)
	at java.lang.StringBuilder.append(StringBuilder.java:115)
	at org.apache.cxf.endpoint.ClientImpl.onMessage(ClientImpl.java:731)
...
"JSFqueue-threads - 234" prio=10 tid=0x00007f460851d000 nid=0x5c07 runnable [0x00007f45b41b7000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.AbstractStringBuilder.<init>(AbstractStringBuilder.java:45)
	at java.lang.StringBuilder.<init>(StringBuilder.java:68)
	at java.lang.Object.toString(Object.java:219)
	at java.lang.String.valueOf(String.java:2826)
	at java.util.Arrays.toString(Arrays.java:4071)
	at java.util.concurrent.CopyOnWriteArrayList.toString(CopyOnWriteArrayList.java:860)
	at java.lang.String.valueOf(String.java:2826)
	at java.lang.StringBuilder.append(StringBuilder.java:115)
	at org.apache.cxf.endpoint.ClientImpl.setupInterceptorChain(ClientImpl.java:946)

Resolution

• Disable FINE/DEBUG level logging for org.apache.cxf.endpoint.ClientImpl and org.apache.cxf in general.

Root Cause

• FINE level logging is enabled. With this enabled, strings are appended together to form the potential FINE message. Those strings result in array copies and with cxf here can involve arrays several mbs in size. Copying and duplicating arrays several mbs in size like this churns up a lot of short lived objects that quickly turns into garbage, rapidly filling the heap and causing a lot of GC.

Diagnostic Steps

• Use the following OQL in mat to confirm the actual log levels currently used from a heap dump (500 is FINE level):

    SELECT toString(s.name), s.loggerNode.effectiveLevel FROM org.jboss.logmanager.Logger s 
  

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.