For one installation of our application we have been seeing issues on production that were reported as "system is getting slower" or "requests never returning" by the users. In the end the server had to be restarted. We had several of those incidents and a nightly restart of the server seems to be working as a workaround.
Our application makes heavy use of dynamic classloading (.jar files stored in database as blobs) and reflection. Environment details:
- Java 1.7.021
- OS: Linux (2.6.32-504.16.2.el6.x86_64)
- JBoss EAP 6.2
- Appdynamics is beeing used
- memory and gc settings: -XX:PermSize=256m -XX:MaxPermSize=2560m -Xms2048m -Xmx10240m -server -XX:+UseParallelGC -XX:+UseParallelOldGC
We switched to
- Java 1.7.080
- -XX:+UseG1GC
but it looks like we are still facing the issue.
What we are seeing in the logfiles, heapdumps, threadumps and gc logs so fare is the following
- We are not seeing any OutOfMemory errors
- Memory consumption of both Heap and PermGend seems to be ok (heap and perm gen not fully used)
- With Java 1.7.021 and parallelGC we saw a couple of long running (5 minutes) Full GCs - this does not seem to happen anymore after switching to G1GC (which is what we expected)
- we don't see any warnings related to the CodeCache beeing full in the logs
What we are seeing is
- for some of the incidents the number of DelegatingClassLoaders in the heapdump was around 5000 for others it was around 100 000.
- that after initial reports from users that the system is getting slow the number of threads that are in state RUNNABLE and are working on "getDeclaredConstructors0" is increasing (from just two in the beginning to around 50. The thread seems to "hang" at the same position (well they are in state RUNNABLE) for multiple hours.
See below for an excerpt of the threadump:
"http-xxx:8443-141" daemon prio=10 tid=0x00007efe9412f000 nid=0x64fb runnable [0x00007efe1ba8a000]
java.lang.Thread.State: RUNNABLE
at java.lang.Class.getDeclaredConstructors0(Native Method)
at java.lang.Class.privateGetDeclaredConstructors(Class.java:2413)
at java.lang.Class.getConstructor0(Class.java:2723)
at java.lang.Class.newInstance0(Class.java:345)
at java.lang.Class.newInstance(Class.java:327)
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:399)
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:396)
at java.security.AccessController.doPrivileged(Native Method)
at sun.reflect.MethodAccessorGenerator.generate(MethodAccessorGenerator.java:395)
at sun.reflect.MethodAccessorGenerator.generateMethod(MethodAccessorGenerator.java:77)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:46)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
[application code]
"http-xxx:8443-138" daemon prio=10 tid=0x00007efe9412a000 nid=0x64ed runnable [0x00007efe1c397000]
java.lang.Thread.State: RUNNABLE
at java.lang.Class.getDeclaredConstructors0(Native Method)
at java.lang.Class.privateGetDeclaredConstructors(Class.java:2413)
at java.lang.Class.getConstructor0(Class.java:2723)
at java.lang.Class.newInstance0(Class.java:345)
at java.lang.Class.newInstance(Class.java:327)
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:399)
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:396)
at java.security.AccessController.doPrivileged(Native Method)
at sun.reflect.MethodAccessorGenerator.generate(MethodAccessorGenerator.java:395)
at sun.reflect.MethodAccessorGenerator.generateMethod(MethodAccessorGenerator.java:77)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:46)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at org.mvel2.PropertyAccessor.set(PropertyAccessor.java:350)
at org.mvel2.PropertyAccessor.set(PropertyAccessor.java:134)
at org.mvel2.MVEL.setProperty(MVEL.java:1088)
[application code]
The situation after updating to Java 1.7.80 / G1Gc seems to be similar. Unfortunately no threadump available, just wicket warnings in the log)
2016-03-10 15:00:39,009 WARN [http-xxx:7443-23] org.apache.wicket.page.PageAccessSynchronizer: Thread 'http-xxx:7443-23' failed to acquire lock to page with id '28', attempted for 3 minutes out of allowed 3 minutes. The thread that holds the lock has name 'http-xxx:7443-18'.
2016-03-10 15:00:39,017 WARN [http-xxx:7443-23] org.apache.wicket.page.PageAccessSynchronizer: "http-xxx:7443-18" daemon prio=5 tid=8950 state=RUNNABLE
org.apache.wicket.util.lang.Threads$ThreadDump
at java.lang.Class.getDeclaredConstructors0(Native Method)
at java.lang.Class.privateGetDeclaredConstructors(Class.java:2595)
at java.lang.Class.getConstructor0(Class.java:2895)
at java.lang.Class.newInstance(Class.java:354)
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:399)
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:396)
at java.security.AccessController.doPrivileged(Native Method)
at sun.reflect.MethodAccessorGenerator.generate(MethodAccessorGenerator.java:395)
at sun.reflect.MethodAccessorGenerator.generateSerializationConstructor(MethodAccessorGenerator.java:113)
at sun.reflect.ReflectionFactory.newConstructorForSerialization(ReflectionFactory.java:331)
at java.io.ObjectStreamClass.getSerializableConstructor(ObjectStreamClass.java:1376)
at java.io.ObjectStreamClass.access$1500(ObjectStreamClass.java:72)
at java.io.ObjectStreamClass$2.run(ObjectStreamClass.java:493)
at java.io.ObjectStreamClass$2.run(ObjectStreamClass.java:468)
at java.security.AccessController.doPrivileged(Native Method)
at java.io.ObjectStreamClass.<init>(ObjectStreamClass.java:468)
at java.io.ObjectStreamClass.lookup(ObjectStreamClass.java:365)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1133)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:347)
[application code]
2016-03-10 15:04:14,640 WARN [http-xxx:7443-16] org.apache.wicket.page.PageAccessSynchronizer: Thread 'http-xxx:7443-16' failed to acquire lock to page with id '11', attempted for 3 minutes out of allowed 3 minutes. The thread that holds the lock has name 'http-xxx:7443-38'.
2016-03-10 15:04:14,642 WARN [http-xxx:7443-16] org.apache.wicket.page.PageAccessSynchronizer: "http-xxx:7443-38" daemon prio=5 tid=9088 state=RUNNABLE
org.apache.wicket.util.lang.Threads$ThreadDump
at java.lang.Class.getDeclaredConstructors0(Native Method)
at java.lang.Class.privateGetDeclaredConstructors(Class.java:2595)
at java.lang.Class.getConstructor0(Class.java:2895)
at java.lang.Class.newInstance(Class.java:354)
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:399)
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:396)
at java.security.AccessController.doPrivileged(Native Method)
at sun.reflect.MethodAccessorGenerator.generate(MethodAccessorGenerator.java:395)
at sun.reflect.MethodAccessorGenerator.generateMethod(MethodAccessorGenerator.java:77)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:46)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
[application code]
We are currently unable to reproduce this (still working on that). But maybe somebody in the community has seen something similar and has an idea what could help us to reproduce or solve the issues. One guess that we currently having is that this is related to native memory consumption (Because of information like http://ift.tt/1ELFwwK) but we don't see any hints in this regards in the logs (no OutOfMemory errors, no reports from the linux administrators that the system is running out of memory)
Aucun commentaire:
Enregistrer un commentaire