We use mozlia rhino to generate dynamic class, then load JsClass by custom classloader like this
DynamicClassLoader loader = new DynamicClassLoader(JavaScriptFactory.class.getClassLoader());
Class<?> jsClass = loader.loadClass("D://","com.huawei.xxx");
jsClass.newInstance();
As you see, every JsClass have a seperate classloader, when user modify js, we will also reload JsClass by this code,
Now, we face a problem, when call jsClass.newInstance(), some thread hang at getDeclaredConstructors0 for a long time(3s-1000s), normally it shoud be less then 10ms. Can someone tell me the possiable reason? Thanks very much!
JDK: 1.8.0.60
Tomcat: 7.0.59
JvmArgs:
-Dnop -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -DDN=mateinfo_app -server -Duser.timezone=GMT -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=80 -XX:+DisableExplicitGC -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintGCDetails -Xloggc:/opt/mateinfo/logs/app/tomcat-gc-20160601-233343.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/mateinfo/logs/app/oom-20160601-233343.bin -XX:OnOutOfMemoryError=./deal-oom.sh -Xms3260m -Xmx3260m -Xmn800m -XX:MetaspaceSize=800m -XX:MaxMetaspaceSize=800m -XX:SurvivorRatio=16 -XX:+OptimizeStringConcat -Xverify:all -Dsoapui.log4j.config=/opt/mateinfo/app/lib/log4j.properties -Dlog4j.ignoreTCL=true -XX:-OmitStackTraceInFastThrow -Xrunjdwp:transport=dt_socket,address=8000,server=y,suspend=n -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=8050 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Djava.net.preferIPv4Stack=true -Djava.endorsed.dirs=/opt/mateinfo/app/endorsed -classpath /opt/mateinfo/app/bin/bootstrap.jar:/opt/mateinfo/app/bin/tomcat-juli.jar -Dcatalina.base=/opt/mateinfo/app -Dcatalina.home=/opt/mateinfo/app -Djava.io.tmpdir=/opt/mateinfo/app/temp org.apache.catalina.startup.Bootstrap start
Thread Dump:
----------------- 7123 -----------------
0x00007f9d44cdc6d5 __pthread_cond_wait + 0xc5
0x00007f9d43cc157c _ZN15JvmtiRawMonitor11SimpleEnterEP6Thread + 0xdc
0x00007f9d43cc1c07 _ZN15JvmtiRawMonitor9raw_enterEP6Thread + 0xd7
0x00007f9d43c9a2ed _ZN8JvmtiEnv15RawMonitorEnterEP15JvmtiRawMonitor + 0xad
0x00007f9d429c4df8 debugMonitorEnter + 0x38
0x00007f9d429b1451 event_callback + 0x2e1
0x00007f9d429b1e8e cbClassPrepare + 0x8e
0x00007f9d43cb0beb _ZN11JvmtiExport18post_class_prepareEP10JavaThreadP5Klass + 0x15b
0x00007f9d43b59f31 _ZN13InstanceKlass15link_class_implE19instanceKlassHandlebP6Thread + 0x3f1
0x00007f9d43b5a0d4 _ZN13InstanceKlass10link_classEP6Thread + 0x54
0x00007f9d43c3ec49 _ZL33get_class_declared_methods_helperP7JNIEnv_P7_jclasshbP5KlassP6Thread + 0xc9
0x00007f9d43c3f28e JVM_GetClassDeclaredConstructors + 0xce
"app-JavaScriptFactory-7-thread-1" #41621 prio=5 os_prio=0 tid=0x00007f9d1d7f9800 nid=0x1bd3 runnable [0x00007f9c8040e000]
java.lang.Thread.State: RUNNABLE
at java.lang.Class.getDeclaredConstructors0(Native Method)
at java.lang.Class.privateGetDeclaredConstructors(Class.java:2671)
at java.lang.Class.getConstructor0(Class.java:3075)
at java.lang.Class.newInstance(Class.java:412)
at com.huawei.sdm.integration.message.runtime.handler.script.JsBeanGenerateRunner.excute(JsBeanGenerateRunner.java:82)
at com.huawei.mateinfo.context.support.CommonCallable.call(CommonCallable.java:31)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
GCLog:
{Heap before GC invocations=331320 (full 1587):
par new generation total 773696K, used 732120K [0x00000006f4400000, 0x0000000726400000, 0x0000000726400000)
eden space 728192K, 100% used [0x00000006f4400000, 0x0000000720b20000, 0x0000000720b20000)
from space 45504K, 8% used [0x0000000723790000, 0x0000000723b66170, 0x0000000726400000)
to space 45504K, 0% used [0x0000000720b20000, 0x0000000720b20000, 0x0000000723790000)
concurrent mark-sweep generation total 2519040K, used 2123204K [0x0000000726400000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 341907K, capacity 402760K, committed 687488K, reserved 1640448K
class space used 38870K, capacity 47018K, committed 95616K, reserved 1048576K
2016-05-31T12:47:08.303+0000: 550384.634: [GC (GCLocker Initiated GC) 2016-05-31T12:47:08.303+0000: 550384.634: [ParNew: 732120K->2438K(773696K), 0.0228934 secs] 2855324K->2125771K(3292736K), 0.0231999 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]
Heap after GC invocations=331321 (full 1587):
par new generation total 773696K, used 2438K [0x00000006f4400000, 0x0000000726400000, 0x0000000726400000)
eden space 728192K, 0% used [0x00000006f4400000, 0x00000006f4400000, 0x0000000720b20000)
from space 45504K, 5% used [0x0000000720b20000, 0x0000000720d81bc8, 0x0000000723790000)
to space 45504K, 0% used [0x0000000723790000, 0x0000000723790000, 0x0000000726400000)
concurrent mark-sweep generation total 2519040K, used 2123332K [0x0000000726400000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 341907K, capacity 402760K, committed 687488K, reserved 1640448K
class space used 38870K, capacity 47018K, committed 95616K, reserved 1048576K
}
2016-05-31T12:47:08.334+0000: 550384.665: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2123332K(2519040K)] 2135637K(3292736K), 0.0151574 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
2016-05-31T12:47:08.349+0000: 550384.681: [CMS-concurrent-mark-start]
{Heap before GC invocations=331321 (full 1588):
par new generation total 773696K, used 730630K [0x00000006f4400000, 0x0000000726400000, 0x0000000726400000)
eden space 728192K, 100% used [0x00000006f4400000, 0x0000000720b20000, 0x0000000720b20000)
from space 45504K, 5% used [0x0000000720b20000, 0x0000000720d81bc8, 0x0000000723790000)
to space 45504K, 0% used [0x0000000723790000, 0x0000000723790000, 0x0000000726400000)
concurrent mark-sweep generation total 2519040K, used 2123332K [0x0000000726400000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 341907K, capacity 402760K, committed 687488K, reserved 1640448K
class space used 38870K, capacity 47018K, committed 95616K, reserved 1048576K
2016-05-31T12:47:09.419+0000: 550385.751: [GC (Allocation Failure) 2016-05-31T12:47:09.419+0000: 550385.751: [ParNew: 730630K->11995K(773696K), 0.0311341 secs] 2853963K->2135459K(3292736K), 0.0314510 secs] [Times: user=0.10 sys=0.00, real=0.03 secs]
Heap after GC invocations=331322 (full 1588):
par new generation total 773696K, used 11995K [0x00000006f4400000, 0x0000000726400000, 0x0000000726400000)
eden space 728192K, 0% used [0x00000006f4400000, 0x00000006f4400000, 0x0000000720b20000)
from space 45504K, 26% used [0x0000000723790000, 0x0000000724346f10, 0x0000000726400000)
to space 45504K, 0% used [0x0000000720b20000, 0x0000000720b20000, 0x0000000723790000)
concurrent mark-sweep generation total 2519040K, used 2123463K [0x0000000726400000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 341907K, capacity 402760K, committed 687488K, reserved 1640448K
class space used 38870K, capacity 47018K, committed 95616K, reserved 1048576K
}