Long story short, I did a lot of Thread Dumps to come to the conclusion that during my Tomcat slow-down, the creation of int array with 1 or 2 items becomes the bottleneck of many codes of my system. For details, please read on.
This situation has happened a lot of times, and each time it happens, I have to restart the Tomcat to resume to normal speed.
My Tomcat server is running okay. But after around a week (mostly ranging from 4 days to 10 days), my Tomcat becomes slow for most operations. To check why, I have created some benchmarking functions, run them, and take many Thread Dumps.
One of my benchmarking function is as follows:
while (System.currentTimeMillis() < someEndTime) { // I run this loop for 5 seconds
2.power(3) // Note that this function is Groovy code
loopCount++
}
// The higher the loopCount after the loop is passed, the faster it is
Note that I take my Thread Dumps in 2 periods: the "slow period" and also the "normal period".
In the "slow period", the variable loopCount is about one-tenth of its value during the "normal period", meaning it is 10 times slower.
In the slow period, out of 10 Thread Dumps, 8 of them are as follows:
"http-nio-8443-exec-43" daemon prio=6 tid=0x000000004be6a000 nid=0x58f4 runnable [0x0000000067bcc000]
java.lang.Thread.State: RUNNABLE
at java.math.BigInteger.pow(BigInteger.java:1402)
at org.codehaus.groovy.runtime.DefaultGroovyMethods.power(DefaultGroovyMethods.java:8984)
at org.codehaus.groovy.runtime.dgm$473.invoke(Unknown Source)
at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoMetaMethodSiteNoUnwrapNoCoerce.invoke(PojoMetaMethodSite.java:270)
at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:52)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:124)
at com.mycompany.myproduct.TestController$_closure11.doCall(TestController.groovy:241)
The JDK of my Tomcat server is JDK7 Update 75, so BigInteger.java:1402 corresponds to:
int[] result = {1};
which is a single item array creation.
The remaing 2 Thread Dumps (out of the 10) are as follows:
"http-nio-8443-exec-38" daemon prio=6 tid=0x000000005e5f8000 nid=0x22e0 runnable [0x0000000063f9c000]
java.lang.Thread.State: RUNNABLE
at java.util.Arrays.copyOfRange(Arrays.java:2622)
at java.math.BigInteger.trustedStripLeadingZeroInts(BigInteger.java:2826)
at java.math.BigInteger.pow(BigInteger.java:1412)
at org.codehaus.groovy.runtime.DefaultGroovyMethods.power(DefaultGroovyMethods.java:8984)
at org.codehaus.groovy.runtime.dgm$473.invoke(Unknown Source)
at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoMetaMethodSiteNoUnwrapNoCoerce.invoke(PojoMetaMethodSite.java:270)
at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:52)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:124)
at com.mycompany.myproduct.TestController$_closure11.doCall(TestController.groovy:241)
and in the same JDK, Arrays.java:2622 corresponds to:
int[] copy = new int[newLength];
which also an array creation of 1 or 2 items (for 2.power(3), newLength is at most 2, if you copy the related JDK source code and test it).
Out of 10 Thread Dumps in the "slow period", all stack traces are at the creation of int array with 1 to 2 items. This proves the bottleneck in the "slow period" is on the creation of int array with 1 to 2 items.
Also, the memory didn't fill up. The peak heap usage was 7GB over the last week, while the max heap size was 24GB. Also, if the memory was full, there would be plenty of other much larger objects (e.g. the BigInteger itself) than a 2-item array to become the memory allocation bottleneck, and the stack trace of the "slow period" would be different.
When the "slow period" happens, I have to restart the Tomcat to make the speed return to normal.
During "normal period" when my Tomcat is generally several times faster, I also take several Thread Dumps of the same benchmarking function. And I see nothing about array creation being the bottleneck. Belows are the examples:
"http-nio-8443-exec-4" daemon prio=6 tid=0x000000004d22b000 nid=0x163c runnable [0x000000005820a000]
java.lang.Thread.State: RUNNABLE
at org.codehaus.groovy.runtime.typehandling.LongMath.compareToImpl(LongMath.java:50)
at org.codehaus.groovy.runtime.typehandling.NumberMath.compareTo(NumberMath.java:69)
at org.codehaus.groovy.runtime.DefaultGroovyMethods.compareTo(DefaultGroovyMethods.java:8791)
at org.codehaus.groovy.runtime.typehandling.DefaultTypeTransformation.compareToWithEqualityCheck(DefaultTypeTransformation.java:540)
at org.codehaus.groovy.runtime.typehandling.DefaultTypeTransformation.compareTo(DefaultTypeTransformation.java:521)
at org.codehaus.groovy.runtime.ScriptBytecodeAdapter.compareTo(ScriptBytecodeAdapter.java:692)
at org.codehaus.groovy.runtime.ScriptBytecodeAdapter.compareLessThan(ScriptBytecodeAdapter.java:701)
at com.mycompany.myproduct.TestController$_closure11.doCall(TestController.groovy:240)
"http-nio-8443-exec-22" daemon prio=6 tid=0x000000004d248000 nid=0x1988 runnable [0x0000000059b6c000]
java.lang.Thread.State: RUNNABLE
at java.math.BigInteger.pow(BigInteger.java:1406)
at org.codehaus.groovy.runtime.DefaultGroovyMethods.power(DefaultGroovyMethods.java:8984)
at org.codehaus.groovy.runtime.dgm$473.invoke(Unknown Source)
at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoMetaMethodSiteNoUnwrapNoCoerce.invoke(PojoMetaMethodSite.java:270)
at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:52)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:124)
at com.mycompany.myproduct.TestController$_closure11.doCall(TestController.groovy:241)
"http-nio-8443-exec-14" daemon prio=6 tid=0x000000004d242000 nid=0x7790 runnable [0x000000005910c000]
java.lang.Thread.State: RUNNABLE
at org.codehaus.groovy.runtime.DefaultGroovyMethods.power(DefaultGroovyMethods.java:8984)
at org.codehaus.groovy.runtime.dgm$473.invoke(Unknown Source)
at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoMetaMethodSiteNoUnwrapNoCoerce.invoke(PojoMetaMethodSite.java:270)
at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:52)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:124)
at com.mycompany.myproduct.TestController$_closure11.doCall(TestController.groovy:241)
DefaultGroovyMethods is part of the Groovy distribution (version 1.7.5).
To summarize, my question is: Why does the creation of int array with 1 to 2 items suddenly become slow and become the bottleneck in the "slow period" of Tomcat, after running from, say, 4 days to 10 days? Why would the creation of such arrays be slower than other parts of the codes?
It seems it is related to the JVM itself, so maybe the developers on the JDK know more about this issue.
My server configurations:
Windows Server 2008 R2 Enterprise Service Pack 1 (64-bit)
48 RAM
Tomcat Java options:
-Xms256m -Xmx24576m -XX:NewSize=64m -XX:PermSize=64m -XX:MaxNewSize=1024m -XX:MaxPermSize=1536m -Dcatalina.home=C:\mycompany\Tomcat7 OF MYPRODUCT -Dcatalina.base=C:\mycompany\Tomcat7 OF MYPRODUCT -Djava.endorsed.dirs=C:\mycompany\Tomcat7 OF MYPRODUCT\endorsed -Djava.io.tmpdir=C:\mycompany\Tomcat7 OF MYPRODUCT\temp -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.util.logging.config.file=C:\mycompany\Tomcat7 OF MYPRODUCT\conf\logging.properties -Dstringchararrayaccessor.disabled=trueJDK7 Update 75 64-bit (path is C:\Program Files\Java\jdk1.7.0_75\jre\bin\server\jvm.dll)
- Groovy 1.7.5
- Grails 1.3.5
Output from running the version.bat:
Server version: Apache Tomcat/7.0.59 Server built: Jan 28 2015 15:51:10 UTC Server number: 7.0.59.0 OS Name: Windows Server 2008 R2 OS Version: 6.1 Architecture: amd64 JVM Version: 1.7.0_75-b13 JVM Vendor: Oracle Corporation
